Log timing of each HTTP call.

diff --git a/bin/sync.pl b/bin/sync.pl
index cec919953933224f87aa4e2c4f50bfc93eb5c737..8f2c3b06d19fb89d4a9268fd2963305b99488a73 100644 (file)
--- a/bin/sync.pl
+++ b/bin/sync.pl
@@ -38,6 +38,12 @@ my %rgb = (
        }
 );
 
+sub log_timing {
+       my ($start, $msg) = @_;
+       my $elapsed = Time::HiRes::tv_interval($start);
+       printf "%s: %.0f ms.\n", $msg, 1e3 * $elapsed;
+}
+
 sub get_oauth_bearer_token {
        my $ua = shift;
        my $now = time();
@@ -49,9 +55,11 @@ sub get_oauth_bearer_token {
                "iat" => $now,
        });
        my $jws_token = Crypt::JWT::encode_jwt(payload=>$jwt, alg=>'RS256', key=>\$config::jwt_key->{'private_key'});
+       my $start = [Time::HiRes::gettimeofday];
        my $response = $ua->post('https://www.googleapis.com/oauth2/v4/token', [
                'grant_type' => 'urn:ietf:params:oauth:grant-type:jwt-bearer',
                'assertion' => $jws_token ]);
+       log_timing($start, '/oauth2/v4/token');
        return JSON::XS::decode_json($response->decoded_content)->{'access_token'};
 }
 
@@ -60,7 +68,9 @@ sub get_slack_name {
        my $req = HTTP::Request->new('GET', 'https://slack.com/api/users.info?user=' . $userid, [
               'Authorization' => 'Bearer ' . $config::slack_oauth_token
        ]);
+       my $start = [Time::HiRes::gettimeofday];
        my $response = $ua->request($req);
+       log_timing($start, '/users.info');
        die $response->status_line if !$response->is_success;
 
        my $user_json = JSON::XS::decode_json($response->decoded_content);
@@ -147,12 +157,14 @@ sub sheet_batch_update {
        my $update = {
                requests => \@requests
        };
+       my $start = [Time::HiRes::gettimeofday];
        my $response = $ua->post(
                'https://sheets.googleapis.com/v4/spreadsheets/' . $config::sheet_id . ':batchUpdate?key=' . $config::gsheets_api_key,
                Content => JSON::XS::encode_json($update),
                Content_type => 'application/json;charset=UTF-8',
                Authorization => 'Bearer ' . $token
        );
+       log_timing($start, '/spreadsheets/values:batchUpdate');
        die $response->decoded_content if !$response->is_success;
 }
 
@@ -225,9 +237,11 @@ sub get_spreadsheet_with_title {
        my ($ua, $token, $wanted_sheet_title) = @_;
 
        # See if we have any spreadsheets that match this title.
+       my $start = [Time::HiRes::gettimeofday];
        my $response = $ua->get('https://sheets.googleapis.com/v4/spreadsheets/' . $config::sheet_id . '?key=' . $config::gsheets_api_key . '&fields=sheets/properties',
                Authorization => 'Bearer ' . $token
        );
+       log_timing($start, '/v4/spreadsheets/properties');
        my $sheets_json = JSON::XS::decode_json($response->decoded_content);
        my ($tab_name, $tab_id);
        for my $sheet (@{$sheets_json->{'sheets'}}) {
@@ -407,12 +421,14 @@ sub possibly_nag_user {
                user => $userid,
                text => $msg
        };
+       my $start = [Time::HiRes::gettimeofday];
        my $response = $ua->post(
                'https://slack.com/api/chat.postEphemeral',
                Content => JSON::XS::encode_json($content),
                Content_type => 'application/json;charset=UTF-8',
                Authorization => 'Bearer ' . $config::slack_oauth_token
        );
+       log_timing($start, 'chat.postEphemeral');
        die $response->status_line if !$response->is_success;
        my $msg_json = JSON::XS::decode_json($response->decoded_content);
        die "Something went wrong: " . $response->decoded_content if (!defined($msg_json) || !$msg_json->{'ok'});
@@ -422,7 +438,7 @@ sub possibly_nag_user {
 }
 
 sub run {
-       my $start = [Time::HiRes::gettimeofday];
+       my $total_start = [Time::HiRes::gettimeofday];
 
        @log = ();
        skv_log("Siste sync startet: " . POSIX::ctime(time));
@@ -481,9 +497,11 @@ sub run {
        }
 
        # Get the list of all people in the sheet (we're going to need them soon anyway).
+       my $start = [Time::HiRes::gettimeofday];
        my $response = $ua->get('https://sheets.googleapis.com/v4/spreadsheets/' . $config::sheet_id . '?key=' . $config::gsheets_api_key . '&ranges=' . $tab_name . '!A4:Z5000&fields=sheets/data/rowData/values/userEnteredValue',
                Authorization => 'Bearer ' . $token
        );
+       log_timing($start, "/spreadsheets/$tab_name");
        my $main_sheet_json = JSON::XS::decode_json($response->decoded_content);
 
        # Update the list of groups we've seen people in.
@@ -505,9 +523,12 @@ sub run {
        my %slack_userid_to_real_name = ();
        my %slack_userid_to_slack_name = ();
        my %slack_userid_to_row = ();
+
+       $start = [Time::HiRes::gettimeofday];
        $response = $ua->get('https://sheets.googleapis.com/v4/spreadsheets/' . $config::sheet_id . '?key=' . $config::gsheets_api_key . '&ranges=Slack-mapping!A5:C5000&fields=sheets/data/rowData/values/userEnteredValue',
                Authorization => 'Bearer ' . $token
        );
+       log_timing($start, "/spreadsheets/Slack-mapping");
        my $mapping_sheet_json = JSON::XS::decode_json($response->decoded_content);
        my $mapping_sheet_rows = $mapping_sheet_json->{'sheets'}[0]{'data'}[0]{'rowData'};
        my $cur_row = 5;
@@ -593,12 +614,14 @@ sub run {
                valueInputOption => 'USER_ENTERED',
                data => \@slack_mapping_updates
        };
+       $start = [Time::HiRes::gettimeofday];
        $response = $ua->post(
                'https://sheets.googleapis.com/v4/spreadsheets/' . $config::sheet_id . '/values:batchUpdate?key=' . $config::gsheets_api_key,
                Content => JSON::XS::encode_json($update),
                Content_type => 'application/json;charset=UTF-8',
                Authorization => 'Bearer ' . $token
        );
+       log_timing($start, "/spreadsheets/values:batchUpdate");
        die $response->decoded_content if (!$response->is_success);
 
        # Now that we have Slack names, we can log double-reacters.
@@ -712,7 +735,7 @@ sub run {
        sheet_batch_update($ua, $token, \@yellow_updates);
        $dbh->commit;
 
-       my $elapsed = Time::HiRes::tv_interval($start);
+       my $elapsed = Time::HiRes::tv_interval($total_start);
        printf "Tok %.0f ms.\n", 1e3 * $elapsed;
 }