Profile YSQL time

new_session_count.awk

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

  # 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;

  # InitPostgres
  if ( action ~ /InitPostgres:$/ )
    new_sessions++;
}
END {
  total_overall_time=time-overall_begin_time;
  printf "total time in output:    %15.2f s\n", total_overall_time;
  printf "total new sessions  :  %14d\nnew sessions per second: %15.2f per second\n", new_sessions, new_sessions/total_overall_time;
}

new_session_count.sh

PG=/home/yugabyte/yb-software/yugabyte-2.7.2.0-b197-centos-x86_64/postgres/bin/postgres
perf probe -x $PG InitPostgres
# perf record -e 'probe_postgres:*'

profile.awk

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

  # 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;

  # InitPostgres
  if ( action ~ /InitPostgres:$/ ) {
    if ( previous_activity_time[pid] == "" ) {
      previous_activity_time[pid]=time;
      previous_activity_state[pid]="0";
      previous_activity_cmd_str[pid]="(InitPostgres)";
      activity_counter[pid]++;
      step_detail_counter[pid][activity_counter[pid]]=1;
      step_detail_activity[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]="==";
    }
  }
  if ( action ~ /InitPostgres__return:$/ ) {
    if ( previous_activity_time[pid] != "" ) {
      total_activity_time[pid][previous_activity_state[pid]]+=time-previous_activity_time[pid];
      total_activity_count[pid][previous_activity_state[pid]]++;
      step_activity_state[pid][activity_counter[pid]]=previous_activity_state[pid];
      step_activity_time[pid][activity_counter[pid]]=time-previous_activity_time[pid];
      step_activity_cmd_str[pid][activity_counter[pid]]=previous_activity_cmd_str[pid];
      step_detail_time[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]=time-previous_activity_time[pid];
      previous_activity_time[pid]=time;
      previous_activity_state[pid]=strtonum(state);
      previous_activity_cmd_str[pid]=cmd_str;
      activity_counter[pid]++;
      step_detail_counter[pid][activity_counter[pid]]=0;
    }
  }
  # 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 ( previous_activity_time[pid] == "" ) {
      previous_activity_time[pid]=time;
      previous_activity_state[pid]=strtonum(state);
      previous_activity_cmd_str[pid]=cmd_str;
      activity_counter[pid]++;
      step_detail_counter[pid][activity_counter[pid]]=0;
    } else {
    # here there is a previous activity, so we can add the time to the activity
      total_activity_time[pid][previous_activity_state[pid]]+=time-previous_activity_time[pid];
      total_activity_count[pid][previous_activity_state[pid]]++;
      step_activity_state[pid][activity_counter[pid]]=previous_activity_state[pid];
      step_activity_time[pid][activity_counter[pid]]=time-previous_activity_time[pid];
      step_activity_cmd_str[pid][activity_counter[pid]]=previous_activity_cmd_str[pid];
      previous_activity_time[pid]=time;
      previous_activity_state[pid]=strtonum(state);
      previous_activity_cmd_str[pid]=cmd_str;
      activity_counter[pid]++;
      step_detail_counter[pid][activity_counter[pid]]=0;
    }
  }
  # parsing syntactic
  if ( action ~ /pg_parse_query:$/ ) {
    start_pg_parse_query[pid]=time;
    step_detail_counter[pid][activity_counter[pid]]++;
  }
  if ( action ~ /pg_parse_query__return:$/ ) {
    step_detail_activity[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]="pg_parse_query";
    step_detail_time[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]=time-start_pg_parse_query[pid];
  }
  # parsing semantic
  if ( action ~ /parse_analyze:$/ ) {
    start_parse_analyze[pid]=time;
    step_detail_counter[pid][activity_counter[pid]]++;
  }
  if ( action ~ /parse_analyze__return:$/ ) {
    step_detail_activity[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]="parse_analyze";
    step_detail_time[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]=time-start_parse_analyze[pid];
  }
  # query rewrite
  if ( action ~ /QueryRewrite:$/ ) {
    start_queryrewrite[pid]=time;
    step_detail_counter[pid][activity_counter[pid]]++;
  }
  if ( action ~ /QueryRewrite__return:$/ ) {
    step_detail_activity[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]="QueryRewrite";
    step_detail_time[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]=time-start_queryrewrite[pid];
  }
  # planner
  if ( action ~ /pg_plan_queries:$/ ) {
    start_pg_plan_queries[pid]=time;
    step_detail_counter[pid][activity_counter[pid]]++;
  }
  if ( action ~ /pg_plan_queries__return:$/ ) {
    step_detail_activity[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]="pg_plan_queries";
    step_detail_time[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]=time-start_pg_plan_queries[pid];
  }
  # portalrun
  if ( action ~ /PortalRun:$/ ) {
    start_portalrun[pid]=time;
    step_detail_counter[pid][activity_counter[pid]]++;
  } if ( action ~ /PortalRun__return:$/ ) { step_detail_activity[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]="PortalRun";
    step_detail_time[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]=time-start_portalrun[pid];
  }
  # readyforquery
  if ( action ~ /ReadyForQuery:$/ ) {
    start_readyforquery[pid]=time;
    step_detail_counter[pid][activity_counter[pid]]++;
  }
  if ( action ~ /ReadyForQuery__return:$/ ) {
    step_detail_activity[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]="ReadyForQuery";
    step_detail_time[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]=time-start_readyforquery[pid];
  }

  ################################

  # committransaction
  if ( action ~ /CommitTransactionCommand:$/ ) {
    start_committransactioncommand[pid]=time;
  }
  if ( action ~ /CommitTransactionCommand__return:$/ ) {
    step_subdetail_name[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["CommitTransactionCommand"]+=time-start_committransactioncommand[pid];
    step_subdetail_counter[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["CommitTransactionCommand"]++;
  }
  # systable_getnext
  if ( action ~ /systable_getnext:$/ ) {
    start_systable_getnext[pid]=time;
  }
  if ( action ~ /systable_getnext__return:$/ ) {
    step_subdetail_name[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["systable_getnext"]+=time-start_systable_getnext[pid];
    step_subdetail_counter[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["systable_getnext"]++;
  }
  # YBCPgExecSelect
  if ( action ~ /YBCPgExecSelect:$/ ) {
    start_ybcpgexecselect[pid]=time;
  }
  if ( action ~ /YBCPgExecSelect__return:$/ ) {
    step_subdetail_name[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["YBCPgExecSelect"]+=time-start_ybcpgexecselect[pid];
    step_subdetail_counter[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["YBCPgExecSelect"]++;
    #printf "execselect: %15.6f\n",  step_subdetail_name[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["YBCPgExecSelect"]
  }
  # YBCPgDmlFetch
  if ( action ~ /YBCPgDmlFetch:$/ ) {
    start_ybcpgdmlfetch[pid]=time;
  }
  if ( action ~ /YBCPgDmlFetch__return:$/ ) {
    step_subdetail_name[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["YBCPgDmlFetch"]+=time-start_ybcpgdmlfetch[pid];
    step_subdetail_counter[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["YBCPgDmlFetch"]++;
  }
  # YBCPgStopOperationsBuffering
  if ( action ~ /YBCPgStopOperationsBuffering:$/ ) {
    start_ybcpgstopoperationsbuffering[pid]=time;
  }
  if ( action ~ /YBCPgStopOperationsBuffering__return:$/ ) {
    step_subdetail_name[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["YBCPgStopOperationsBuffering"]+=time-start_ybcpgstopoperationsbuffering[pid];
    step_subdetail_counter[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["YBCPgStopOperationsBuffering"]++;
  }
  # YBCPgCommitTransaction
  if ( action ~ /YBCPgCommitTransaction:$/ ) {
    start_ybcpgcommittransaction[pid]=time;
  }
  if ( action ~ /YBCPgCommitTransaction__return:$/ ) {
    step_subdetail_name[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["YBCPgCommitTransaction"]+=time-start_ybcpgcommittransaction[pid];
    step_subdetail_counter[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["YBCPgCommitTransaction"]++;
  }
  # YBCPgDmlExecWriteOp
  if ( action ~ /YBCPgDmlExecWriteOp:$/ ) {
    start_ybcpgdmlexecwriteop[pid]=time;
  }
  if ( action ~ /YBCPgDmlExecWriteOp__return:$/ ) {
    step_subdetail_name[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["YBCPgDmlExecWriteOp"]+=time-start_ybcpgdmlexecwriteop[pid];
    step_subdetail_counter[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["YBCPgDmlExecWriteOp"]++;
  }
  # ExecScan
  if ( action ~ /ExecScan:$/ ) {
    start_execscan[pid]=time;
  }
  if ( action ~ /ExecScan__return:$/ ) {
    step_subdetail_name[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["ExecScan"]+=time-start_execscan[pid];
    step_subdetail_counter[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["ExecScan"]++;
  }
  # ExecInsert
  if ( action ~ /ExecInsert:$/ ) {
    start_execinsert[pid]=time;
  }
  if ( action ~ /ExecInsert__return:$/ ) {
    step_subdetail_name[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["ExecInsert"]+=time-start_execinsert[pid];
    step_subdetail_counter[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["ExecInsert"]++;
  }
  # ExecUpdate
  if ( action ~ /ExecUpdate:$/ ) {
    start_execupdate[pid]=time;
  }
  if ( action ~ /ExecUpdate__return:$/ ) {
    step_subdetail_name[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["ExecUpdate"]+=time-start_execupdate[pid];
    step_subdetail_counter[pid][activity_counter[pid]][step_detail_counter[pid][activity_counter[pid]]]["ExecUpdate"]++;
  }

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

  for ( pid in step_activity_state ) {
    printf "pid: %7d\n", pid;
    for ( step = 1; step < activity_counter[pid]; step++ ) {
      printf " %-40s # %5d %15.6f s %7.2f %%\n SQL:%s\n", backend_state[step_activity_state[pid][step]], step, step_activity_time[pid][step], step_activity_time[pid][step]/total_overall_time*100, step_activity_cmd_str[pid][step];
      for ( detail_step = 1; detail_step <= step_detail_counter[pid][step]; detail_step++ ) {
        printf "  %-47s %15.6f s\n", step_detail_activity[pid][step][detail_step], step_detail_time[pid][step][detail_step];
        if ( pid in step_subdetail_name && step in step_subdetail_name[pid] && detail_step in step_subdetail_name[pid][step] ) {
          for ( subdetail in step_subdetail_name[pid][step][detail_step] ) {
            printf "   %-38s %7d %15.6f s\n", subdetail, step_subdetail_counter[pid][step][detail_step][subdetail], step_subdetail_name[pid][step][detail_step][subdetail];
          }
        }
      }
    }
    printf "\n";
  }
}

remove_probes.sh

perf probe -d '*'

set_probes.sh

PG=/home/yugabyte/yb-software/yugabyte-2.7.2.0-b197-centos-x86_64/postgres/bin/postgres
LIBYB=/home/yugabyte/yb-software/yugabyte-2.7.2.0-b197-centos-x86_64/postgres/lib/libyb_pgbackend.so
LIBPGGATE=/home/yugabyte/yb-software/yugabyte-2.7.2.0-b197-centos-x86_64/lib/yb/libyb_pggate.so
perf probe -x $PG 'pgstat_report_activity state:u32 cmd_str:string'
perf probe -x $PG pg_parse_query
perf probe -x $PG pg_parse_query%return
perf probe -x $PG parse_analyze
perf probe -x $PG parse_analyze%return
perf probe -x $PG QueryRewrite
perf probe -x $PG QueryRewrite%return
perf probe -x $PG pg_plan_queries
perf probe -x $PG pg_plan_queries%return
perf probe -x $PG PortalRun
perf probe -x $PG PortalRun%return
perf probe -x $PG CommitTransactionCommand
perf probe -x $PG CommitTransactionCommand%return
perf probe -x $PG ReadyForQuery
perf probe -x $PG ReadyForQuery%return
perf probe -x $PG ExecInsert
perf probe -x $PG ExecInsert%return
perf probe -x $PG ExecUpdate
perf probe -x $PG ExecUpdate%return
perf probe -x $PG ExecScan
perf probe -x $PG ExecScan%return
perf probe -x $PG systable_getnext
perf probe -x $PG systable_getnext%return
perf probe -x $PG InitPostgres
perf probe -x $PG InitPostgres%return
#perf probe -x $LIBYB ybc_systable_getnext
#perf probe -x $LIBYB ybc_systable_getnext%return
perf probe -x $LIBPGGATE YBCPgExecSelect
perf probe -x $LIBPGGATE YBCPgExecSelect%return
perf probe -x $LIBPGGATE YBCPgDmlFetch
perf probe -x $LIBPGGATE YBCPgDmlFetch%return
perf probe -x $LIBPGGATE YBCPgStopOperationsBuffering
perf probe -x $LIBPGGATE YBCPgStopOperationsBuffering%return
perf probe -x $LIBPGGATE YBCPgCommitTransaction
perf probe -x $LIBPGGATE YBCPgCommitTransaction%return
perf probe -x $LIBPGGATE YBCPgDmlExecWriteOp
perf probe -x $LIBPGGATE YBCPgDmlExecWriteOp%return
#perf probe -x $PG 'pgstat_report_wait_start $params'
#perf probe -x $PG pgstat_report_wait_end
# perf record -e 'probe_postgres:*' -e 'probe_libyb_pggate:*'