Time is on my side: active time

I hope you hear the Rolling Stones song with the name of this blogpost in your head, and if you don't: visit youtube or even if you hear it in your head you also might go there and play the song.

Tuning a database is all about time, and understanding where time has gone. Sadly, there isn't a facility in postgresql that accounts time spent so that you can calculate the total active time and the average amount of sessions active.

The indicator for the state of a postgres backend can be seen in pg_stat_activity.state in the database, and the states can be seen in the pgstat.h header file.

The function that sets the value in pg_stat_activity.state is pgstat_report_activity, and the state is used as an argument for this function.

This means we can use perf to set a probe on pgstat_report_activity, and get the state from the function's argument list from the CPU register.

My environment looks like this:

• Alma linux 8.4 (x86_64).
• Postgres 11.13 from the PGDG postgres yum repository.

To set a perf probe on pgstat_report_activity and get the state argument use:
perf probe -x /usr/pgsql-11/bin/postgres pgstat_report_activity %di

After the probe is added, it will not do anything. For that you have to record the probe activity. This is done in the following way: perf record -e 'probe_postgres:*'. After execution, the perf executable is busy and recording any probe activity, until you press ctrl-C, which will write the result to a file in the current working directory called perf.data.

If you want to record any execution of function pgstat_report_activity on the system, you can use perf record -e '..'. Additionally, you can use -p PID for recording just one backend process, or -p PID,PID for recording multiple backend processes.

If you recorded activity you are not done yet. You can view the recorded output using perf script, and it looks something like this:

[root@alma-84 ~]# perf script
      postmaster  3288 [000]  6542.445581: probe_postgres:pgstat_report_activity: (6eea90) arg1=0x2
      postmaster  3288 [000]  6542.445731: probe_postgres:pgstat_report_activity: (6eea90) arg1=0x1
      postmaster  3288 [000]  6543.303748: probe_postgres:pgstat_report_activity: (6eea90) arg1=0x2
      postmaster  3288 [000]  6543.303859: probe_postgres:pgstat_report_activity: (6eea90) arg1=0x1
      postmaster  3288 [000]  6543.952743: probe_postgres:pgstat_report_activity: (6eea90) arg1=0x2
      postmaster  3288 [000]  6543.952855: probe_postgres:pgstat_report_activity: (6eea90) arg1=0x1
      postmaster  3133 [001]  6545.933558: probe_postgres:pgstat_report_activity: (6eea90) arg1=0x2
      postmaster  3133 [001]  6545.933734: probe_postgres:pgstat_report_activity: (6eea90) arg1=0x1
      postmaster  3133 [001]  6546.584847: probe_postgres:pgstat_report_activity: (6eea90) arg1=0x2
      postmaster  3133 [001]  6546.584958: probe_postgres:pgstat_report_activity: (6eea90) arg1=0x1
      postmaster  3133 [001]  6547.236539: probe_postgres:pgstat_report_activity: (6eea90) arg1=0x2
      postmaster  3133 [001]  6547.236644: probe_postgres:pgstat_report_activity: (6eea90) arg1=0x1

The first column is the name of the process, the second column is the PID; so I recorded two processes, the third column is the CPU number, fourth column is the relative timestamp, the fifth column is the probe group and name, the sixth column is the probe address, and the seventh column is the extra argument that I requested (%di, which is the CPU register that carries the argument), which indicates the state to which pgstat_report_activity set the backend to: 1=idle, 2=running.

This means that this data needs to be processed in order to make the data meaningful.

I created a small awk script called postgres_activity.awk that processes the data, and prints it in a way that allows you to work with the data. It should be used in the following way:
perf script | ./postgres_activity.awk
From the above raw perf data, it creates the following overview:

[root@alma-84 ~]# perf script | ./dbtime.awk
total time in file                                                    4.791063 s 100.00 %

pid:    3133                                                          1.303086 s  27.20 %
 state idle                                                  2        1.302694 s  99.97 %
 state running                                               3        0.000392 s   0.03 %

pid:    3288                                                          1.507274 s  31.46 %
 state idle                                                  2        1.506901 s  99.98 %
 state running                                               3        0.000373 s   0.02 %

This allows you calculate some statistics that are important for calculating load:

• The total time recorded in the file is 4.791063 seconds.
• The total active time is the sum of the running states: 0.000392+0.000373=0.000765. That is the socalled dbtime.
• This means that the average amount of activity is: 0.000765/4.791063=0.0001596722898. That is the socalled average active session time.

Of course the above numbers are silly, but the principal function of using these numbers isn't: average active session time can be directly used to match with the number of CPUs to see how much CPU load is produced by postgres.

In order to remove the probe, execute:
perf probe --del 'probe_postgres:pgstat_report_activity'
Or even simpler, if you got one probe or want to remove all probes:
perf probe --del '*'