Postgres activity and wait profile

profile.awk

#!/usr/bin/awk -f
{ pid=$2;
  time=$4;
  action=$5;

  # wait groups
  wait_class[0]="unknown";
  wait_class[1]="lwlock";
  wait_class[3]="lock";
  wait_class[4]="buffer_pin";
  wait_class[5]="activity";
  wait_class[6]="client";
  wait_class[7]="extension";
  wait_class[8]="ipc";
  wait_class[9]="timeout";
  wait_class[10]="io";
  # wait events
  wait_event[0][0]="unknown";
  wait_event[5][0]="archiver main";
  wait_event[5][1]="autovacuum main";
  wait_event[5][2]="bgwriter hibernate";
  wait_event[5][3]="bgwriter main";
  wait_event[5][4]="checkpointer main";
  wait_event[5][5]="logical launcer main";
  wait_event[5][6]="logical apply main";
  wait_event[5][7]="pgstat main";
  wait_event[5][8]="recovery wal all";
  wait_event[5][9]="recovery wal stream";
  wait_event[5][10]="syslogger main";
  wait_event[5][11]="wal receiver main";
  wait_event[5][12]="wal sender main";
  wait_event[5][13]="wal writer main";
  wait_event[6][0]="client read";
  wait_event[6][1]="client write";
  wait_event[6][2]="libpqwalreceiver connect";
  wait_event[6][3]="libpqwalreceiver receive";
  wait_event[6][4]="ssl open server";
  wait_event[6][5]="wal receiver wait start";
  wait_event[6][6]="wal sender wait wal";
  wait_event[6][7]="wal sender write data";
  wait_event[8][0]="bgworker shutdown";
  wait_event[8][1]="bgworker startup";
  wait_event[8][2]="btree page hibernate";
  wait_event[8][3]="execute gather";
  wait_event[8][4]="hash batch allocating";
  wait_event[8][5]="hash batch electing";
  wait_event[8][6]="hash batch loading";
  wait_event[8][7]="hash build allocating";
  wait_event[8][8]="hash build electing";
  wait_event[8][9]="hash build hashing inner";
  wait_event[8][10]="hash build hashing outer";
  wait_event[8][11]="hash grow batches electing";
  wait_event[8][12]="hash grow batches finishing";
  wait_event[8][13]="hash grow batches repartitioning";
  wait_event[8][14]="hash grow batches allocating";
  wait_event[8][15]="hash grow batches deciding";
  wait_event[8][16]="hash grow buckets electing";
  wait_event[8][17]="hash grow buckets reinserting";
  wait_event[8][18]="hash grow buckets allocating";
  wait_event[8][19]="logical sync data";
  wait_event[8][20]="logical sync state change";
  wait_event[8][21]="mq internal";
  wait_event[8][22]="mq put message";
  wait_event[8][23]="mq receive";
  wait_event[8][24]="mq send";
  wait_event[8][25]="parallel finish";
  wait_event[8][26]="parallel bitmap scan";
  wait_event[8][27]="parallel create index scan";
  wait_event[8][28]="procarray group update";
  wait_event[8][29]="clog group update";
  wait_event[8][30]="replication origin drop";
  wait_event[8][31]="replication slot drop";
  wait_event[8][32]="safe snapshot";
  wait_event[8][33]="sync rep";
  wait_event[9][0]="base backup throttle";
  wait_event[9][1]="pg sleep";
  wait_event[9][2]="recovery apply delay";
  wait_event[10][0]="buffile read";
  wait_event[10][1]="buffile write";
  wait_event[10][2]="control file read";
  wait_event[10][3]="control file sync";
  wait_event[10][4]="control file sync update";
  wait_event[10][5]="control file write";
  wait_event[10][6]="control file write update";
  wait_event[10][7]="copy file read";
  wait_event[10][8]="copy file write";
  wait_event[10][9]="data file extend";
  wait_event[10][10]="data file flush";
  wait_event[10][11]="data file immediate sync";
  wait_event[10][12]="data file prefetch";
  wait_event[10][13]="data file read";
  wait_event[10][14]="data file sync";
  wait_event[10][15]="data file truncate";
  wait_event[10][16]="data file write";
  wait_event[10][17]="dsm fill zero write";
  wait_event[10][18]="lock file addtodatadir read";
  wait_event[10][19]="lock file addtodatadir sync";
  wait_event[10][20]="lock file addtodatadir write";
  wait_event[10][21]="lock file create read";
  wait_event[10][22]="lock file create sync";
  wait_event[10][23]="lock file create write";
  wait_event[10][24]="lock file recheckdatadir read";
  wait_event[10][25]="logical rewrite checkpoint sync";
  wait_event[10][26]="logical rewrite mapping sync";
  wait_event[10][27]="logical rewrite mapping write";
  wait_event[10][28]="logical rewrite sync";
  wait_event[10][29]="logical rewrite truncate";
  wait_event[10][30]="logical rewrite write";
  wait_event[10][31]="relation map read";
  wait_event[10][32]="relation map sync";
  wait_event[10][33]="relation map write";
  wait_event[10][34]="reorder buffer read";
  wait_event[10][35]="reorder buffer sync";
  wait_event[10][36]="reorder logical mapping read";
  wait_event[10][37]="replication slot read";
  wait_event[10][38]="replication slot restore sync";
  wait_event[10][39]="replication slot sync";
  wait_event[10][40]="replication slot write";
  wait_event[10][41]="slru flush sync";
  wait_event[10][42]="slru read";
  wait_event[10][43]="slru sync";
  wait_event[10][44]="slru write";
  wait_event[10][45]="snapbuild read";
  wait_event[10][46]="snapbuild sync";
  wait_event[10][47]="snapbuild write";
  wait_event[10][48]="timeline history file sync";
  wait_event[10][49]="timeline history file write";
  wait_event[10][50]="timeline history read";
  wait_event[10][51]="timeline history sync";
  wait_event[10][52]="timeline history write";
  wait_event[10][53]="twophase file read";
  wait_event[10][54]="twophase file sync";
  wait_event[10][55]="twophase file write";
  wait_event[10][56]="walsender timeline history read";
  wait_event[10][57]="wal bootstrap sync";
  wait_event[10][58]="wal bootstrap write";
  wait_event[10][59]="wal copy read";
  wait_event[10][60]="wal copy sync";
  wait_event[10][61]="wal copy write";
  wait_event[10][62]="wal init sync";
  wait_event[10][63]="wal init write";
  wait_event[10][64]="wal read";
  wait_event[10][65]="wal sync method assign";
  wait_event[10][66]="wal write";
  # backend state
  backend_state[0]="undefined";
  backend_state[1]="idle";
  backend_state[2]="running";
  backend_state[3]="idle in transaction";
  backend_state[4]="fastpath";
  backend_state[5]="idle in transaction aborted";
  backend_state[6]="disabled";


  # remove colon from time
  time=substr(time,1,length(time)-1);

  # get first relative timestamp in output
  if ( overall_begin_time == "" )
    overall_begin_time = time;

  # get the first relative timestamp for the pid
  if ( begin_time[pid] == "" )
    begin_time[pid] = time;

  # pgstat_report_activity
  if ( action ~ /pgstat_report_activity:$/ ) {
    # cut off the 'state_u32=' prefix and assign the value to the state variable
    state=$7;
    sub("state_u32=","",state);
    # add the remaining fields after state to the variable cmd_str
    # and cut off the 'cmd_str_string="' and '"' at the end
    cmd_str=$8;
    for ( i=9; i<=NF; i++ ) {
      cmd_str=cmd_str " " $i;
    };
    sub(/^cmd_str_string="/,"",cmd_str);
    sub(/"$/,"",cmd_str);
    # if there is no previous activity, we can't subtract time and know time spent
    if ( prev_report_activity_time[pid] == "" ) {
      prev_report_activity_time[pid]=time;
      prev_report_activity_state[pid]=state;
    } else {
    # here there is a previous activity, so we can add the time to the activity
      report_activity_time[pid][prev_report_activity_state[pid]]+=time-prev_report_activity_time[pid];
      report_activity_count[pid][prev_report_activity_state[pid]]++;
      prev_report_activity_time[pid]=time;
      prev_report_activity_state[pid]=state;
    }
  }

  # pgstat_report_wait_start, perf adds a number to the probe name because it results in multiple probes
  if ( action ~ /pgstat_report_wait_start_[0-9]*:$/ ) {
    # wait_event_info, assign dummy value 0x0000000 if no wait event is found, otherwise cut off "wait_event_info="
    wait_event_info=$7;
    if ( wait_event_info == "" ) {
      wait_event_info = "0x0000000";
    } else {
      sub("wait_event_info=","",wait_event_info);
    }
    start_time_wait_event[pid][wait_event_info]=time;
    current_wait_event[pid]=wait_event_info;
  }
  # pgstat_report_wait_end, perf adds a number to the probe name because it results in multiple probes
  if ( action ~/pgstat_report_wait_end_[0-9]*:$/ ) {
    # make sure we don't count an wait_end with no wait_begin
    if ( start_time_wait_event[pid][current_wait_event[pid]] > 0 ) {
      wait_event_time[pid][current_wait_event[pid]]+=time-start_time_wait_event[pid][current_wait_event[pid]];
      start_time_wait_event[pid][current_wait_event[pid]]=0;
      wait_event_count[pid][current_wait_event[pid]]++;
    }
  }

  end_time[pid] = time;
}
END {
  total_overall_time=time-overall_begin_time;
  printf "%-50s             %15.6f s %6.2f %%\n\n", "total time in file", total_overall_time, 100;

  for ( pid in wait_event_time ) {
    printf "pid: %7d                                                   %15.6f s %6.2f %%\n", pid, end_time[pid]-begin_time[pid], (end_time[pid]-begin_time[pid])/total_overall_time*100;
    for ( event in wait_event_time[pid] ) {
      class_number=rshift(strtonum(event),24);
      event_number=strtonum("0x" substr(event,length(event)-4,length(event)));
      printf " %-50s %10d %15.6f s %6.2f %%\n", "event " wait_class[class_number] ":" wait_event[class_number][event_number],wait_event_count[pid][event], wait_event_time[pid][event], wait_event_time[pid][event]/(end_time[pid]-begin_time[pid])*100;
    }
    if ( pid in report_activity_time ) {
      for ( state in report_activity_time[pid] ) {
        printf " %-50s %10d %15.6f s %6.2f %%\n", "state " backend_state[state], report_activity_count[pid][state], report_activity_time[pid][state], report_activity_time[pid][state]/(end_time[pid]-begin_time[pid])*100;
      }
    }
    printf "\n";
  }
}

set_probes.sh

perf probe -x /usr/pgsql-11/bin/postgres 'pgstat_report_activity state:u32 cmd_str:string'
perf probe -x /usr/pgsql-11/bin/postgres 'pgstat_report_wait_start $params'
perf probe -x /usr/pgsql-11/bin/postgres pgstat_report_wait_end