Added TTFB to jetmon #9

darssen · 2022-10-28T22:25:35Z

Added Time To First Byte (TTFB) calculation in the Jetmon monitor.

TTFB calculation

The ttfb is calculated by comparing the time between sending the HEAD call and receiving something on the socket.

Testing instructions

Work done here #8 should help to bring up a docker environment, with that, a Jetpack connected site configured in the DB, and the diff below, jetmon should create a request periodically (even if server doesn't change states) and will send message to wpcom with ttfb info under the extra property.

diff --git a/lib/httpcheck.js b/lib/httpcheck.js
index 11f0f8b..640523b 100644
--- a/lib/httpcheck.js
+++ b/lib/httpcheck.js
 // each worker loads it's own config object
@@ -89,34 +92,26 @@ var HttpChecker = {
                else
                        server.site_status = SITE_CONFIRMED_DOWN;
 
-               var resO    = {};
-               resO.type   = JETMON_CHECK;
-               resO.status = server.site_status;
-               resO.rtt    = Math.round( rtt / 1000 );
-               resO.code   = http_code;
-               resO.ttfb   = Math.round( ttfb / 1000 );
-               server.checks.push( resO );
-               process.send( { msgtype: 'notify_status_change', server: server } );
-
-               //if ( server.site_status !=  server.oldStatus ) {
-               //      var resO    = {};
-               //      resO.type   = JETMON_CHECK;
-               //      resO.status = server.site_status;
-               //      resO.rtt    = Math.round( rtt / 1000 );
-               //      resO.code   = http_code;
-               //      server.checks.push( resO );
-
-               //      // if site is down and it has not been confirmed
-               //      if ( server.site_status == SITE_DOWN ) {
-               //              process.send( { msgtype: 'recheck', server: server } );
-               //      } else if ( SITE_CONFIRMED_DOWN != server.site_status ) {
-               //              process.send( { msgtype: 'notify_status_change', server: server } );
-               //              slogger.trace( 'status_change: ' + JSON.stringify( server ) );
-               //      } else {
-               //              process.send( { msgtype: 'notify_still_down', server: server } );
-               //              slogger.trace( 'still_down: ' + JSON.stringify( server ) );
-               //      }
-               // }
-               // }
+               if ( server.site_status !=  server.oldStatus ) {
+                       var resO    = {};
+                       resO.type   = JETMON_CHECK;
+                       resO.status = server.site_status;
+                       resO.rtt    = Math.round( rtt / 1000 );
+                       resO.code   = http_code;
+                       resO.ttfb   = Math.round( ttfb / 1000 );
+                       server.checks.push( resO );
+
+                       // if site is down and it has not been confirmed
+                       if ( server.site_status == SITE_DOWN ) {
+                               process.send( { msgtype: 'recheck', server: server } );
+                       } else if ( SITE_CONFIRMED_DOWN != server.site_status ) {
+                               process.send( { msgtype: 'notify_status_change', server: server } );
+                               slogger.trace( 'status_change: ' + JSON.stringify( server ) );
+                       } else {
+                               process.send( { msgtype: 'notify_still_down', server: server } );
+                               slogger.trace( 'still_down: ' + JSON.stringify( server ) );
+                       }
+               }

darssen · 2022-10-28T22:44:51Z

Prior to changes in #6 the ttfb timings (~600 ms) we were getting seemed appropriate based on rtt (~1 s) results.
Now I am getting rtt (~1 s) but much lower ttfb (~150 ms).

This was for a JN and a test with online tools shows results similar to initial tests.

The changes seem to be related to the changes in c++ classes rather than the node version. Used old version with changes from the aforementioned PR and get same results.

fgiannar

I can't even get this to build successfully it seems 🤔

I keep getting errors like the following when running node gyp rebuild:

In file included from ../src/http_checker.cpp:2:
../src/http_checker.h:70:7: error: 'chrono' in namespace 'std' does not name a type
  std::chrono::_V2::system_clock::time_point m_tstart;
       ^~~~~~
../src/http_checker.h:70:2: note: suggested alternative: 'crend'
  std::chrono::_V2::system_clock::time_point m_tstart;
  ^~~
  crend
../src/http_checker.h:74:7: error: 'chrono' in namespace 'std' does not name a type
  std::chrono::_V2::system_clock::time_point m_tstart_ttfb;
       ^~~~~~
../src/http_checker.h:74:2: note: suggested alternative: 'crend'
  std::chrono::_V2::system_clock::time_point m_tstart_ttfb;
  ^~~
  crend
../src/http_checker.cpp:5:22: error: 'chrono' is not a namespace-name
 using namespace std::chrono;
                      ^~~~~~
../src/http_checker.cpp:5:22: note: suggested alternative: 'crend'
 using namespace std::chrono;
                      ^~~~~~
                      crend
../src/http_checker.cpp:5:28: error: expected namespace-name before ';' token
 using namespace std::chrono;
                            ^
../src/http_checker.cpp: In constructor 'HTTP_Checker::HTTP_Checker()':
../src/http_checker.cpp:11:2: error: 'm_tstart' was not declared in this scope
  m_tstart = high_resolution_clock::now();
  ^~~~~~~~
../src/http_checker.cpp:11:2: note: suggested alternative: 'va_start'
  m_tstart = high_resolution_clock::now();
  ^~~~~~~~
  va_start
../src/http_checker.cpp:11:13: error: 'high_resolution_clock' has not been declared
  m_tstart = high_resolution_clock::now();
             ^~~~~~~~~~~~~~~~~~~~~
../src/http_checker.cpp: In member function 'int HTTP_Checker::get_rtt()':
../src/http_checker.cpp:22:9: error: 'duration_cast' was not declared in this scope
  return duration_cast<microseconds>(high_resolution_clock::now() - m_tstart).count();
         ^~~~~~~~~~~~~
../src/http_checker.cpp:22:23: error: 'microseconds' was not declared in this scope
  return duration_cast<microseconds>(high_resolution_clock::now() - m_tstart).count();
                       ^~~~~~~~~~~~
../src/http_checker.cpp:22:37: error: 'high_resolution_clock' has not been declared
  return duration_cast<microseconds>(high_resolution_clock::now() - m_tstart).count();
                                     ^~~~~~~~~~~~~~~~~~~~~
../src/http_checker.cpp:22:68: error: 'm_tstart' was not declared in this scope
  return duration_cast<microseconds>(high_resolution_clock::now() - m_tstart).count();
                                                                    ^~~~~~~~
../src/http_checker.cpp:22:68: note: suggested alternative: 'va_start'
  return duration_cast<microseconds>(high_resolution_clock::now() - m_tstart).count();
                                                                    ^~~~~~~~
                                                                    va_start
../src/http_checker.cpp: In member function 'std::__cxx11::string HTTP_Checker::send_http_get()':
../src/http_checker.cpp:185:3: error: 'm_tstart_ttfb' was not declared in this scope
   m_tstart_ttfb = high_resolution_clock::now();
   ^~~~~~~~~~~~~
../src/http_checker.cpp:185:19: error: 'high_resolution_clock' has not been declared
   m_tstart_ttfb = high_resolution_clock::now();
                   ^~~~~~~~~~~~~~~~~~~~~
../src/http_checker.cpp: In member function 'std::__cxx11::string HTTP_Checker::get_response()':
../src/http_checker.cpp:213:13: error: 'duration_cast' was not declared in this scope
    m_ttfb = duration_cast<microseconds>(high_resolution_clock::now() - m_tstart_ttfb).count();
             ^~~~~~~~~~~~~
../src/http_checker.cpp:213:27: error: 'microseconds' was not declared in this scope
    m_ttfb = duration_cast<microseconds>(high_resolution_clock::now() - m_tstart_ttfb).count();
                           ^~~~~~~~~~~~
../src/http_checker.cpp:213:41: error: 'high_resolution_clock' has not been declared
    m_ttfb = duration_cast<microseconds>(high_resolution_clock::now() - m_tstart_ttfb).count();
                                         ^~~~~~~~~~~~~~~~~~~~~
../src/http_checker.cpp:213:72: error: 'm_tstart_ttfb' was not declared in this scope
    m_ttfb = duration_cast<microseconds>(high_resolution_clock::now() - m_tstart_ttfb).count();
                                                                        ^~~~~~~~~~~~~
make: *** [jetmon.target.mk:114: Release/obj.target/jetmon/src/http_checker.o] Error 1
gyp ERR! build error

darssen · 2022-11-01T01:06:21Z

Sorry I missed a library in the header file. Should be building now.

fgiannar · 2022-11-01T08:36:21Z

Prior to changes in #6 the ttfb timings (~600 ms) we were getting seemed appropriate based on rtt (~1 s) results.
Now I am getting rtt (~1 s) but much lower ttfb (~150 ms).

I noticed that we define a different starting point for ttfb and rtt.
ttfb start time m_tstart_ttfb seems to be set when the request starts and does not account for the Connection and TLS negotiation times (which I believe it should), so I wonder if it should be defined earlier, same as rtt start time m_tstart.
When I tried it in my local env I was getting similar results with the byte check online tool.

…etmon

…tiation.

darssen · 2022-11-14T07:00:55Z

Thanks a lot for reviewing this PR.

I noticed that we define a different starting point for ttfb and rtt.
ttfb start time m_tstart_ttfb seems to be set when the request starts and does not account for the Connection and TLS negotiation times (which I believe it should), so I wonder if it should be defined earlier, same as rtt start time m_tstart.

You are right, I have made the change so that it considers the same time start as rtt.

darssen · 2022-11-14T08:05:36Z

I have decided not to include ttfb for Veriflier services, since Veriflier uses Qt framework and have not been able to find a good way to measure it. Also, at the moment, Verifliers are only used to re-confirm a site is down so measuring times in that scenario is not that valuable.

For some more context
readyRead signal appears to be what we need to measure it, but when trying it returns the same as rtt.
Check p1668158341181189-slack-C02NENKA4GN

fgiannar

Looks good though I noticed the changes from #11 seem to be lost. Maybe a result from fixing conflicts?

lib/httpcheck.js

…etmon

fgiannar · 2022-11-15T10:16:15Z

On hold till we finalize our TTFB and RTT approach as per the internal discussion: p9dueE-6cS-p2

Added TTFB to jetmon

05d068b

fgiannar requested changes Oct 31, 2022

View reviewed changes

Added chrono library to headers file.

620cdc7

darssen requested a review from fgiannar November 1, 2022 01:07

Merge branch 'master' of github.com:Automattic/jetmon into add-ttfb-j…

09c45a7

…etmon

darssen self-assigned this Nov 10, 2022

Changed ttfb calculation so that start time considers Connection nego…

8c845d5

…tiation.

fgiannar requested changes Nov 14, 2022

View reviewed changes

lib/httpcheck.js Outdated Show resolved Hide resolved

darssen added 2 commits November 14, 2022 10:13

Merge branch 'master' of github.com:Automattic/jetmon into add-ttfb-j…

e8022dc

…etmon

Removed unnecessary debug

3644420

darssen requested a review from fgiannar November 14, 2022 10:23

darssen added the DO NOT MERGE label Nov 14, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Added TTFB to jetmon #9

Added TTFB to jetmon #9

darssen commented Oct 28, 2022

darssen commented Oct 28, 2022

fgiannar left a comment

darssen commented Nov 1, 2022 •

edited

Loading

fgiannar commented Nov 1, 2022

darssen commented Nov 14, 2022

darssen commented Nov 14, 2022

fgiannar left a comment

fgiannar commented Nov 15, 2022

Added TTFB to jetmon #9

Are you sure you want to change the base?

Added TTFB to jetmon #9

Conversation

darssen commented Oct 28, 2022

TTFB calculation

Testing instructions

darssen commented Oct 28, 2022

fgiannar left a comment

Choose a reason for hiding this comment

darssen commented Nov 1, 2022 • edited Loading

fgiannar commented Nov 1, 2022

darssen commented Nov 14, 2022

darssen commented Nov 14, 2022

fgiannar left a comment

Choose a reason for hiding this comment

fgiannar commented Nov 15, 2022

darssen commented Nov 1, 2022 •

edited

Loading