LCOV - code coverage report
Current view: top level - src/bin/pg_test_timing - pg_test_timing.c (source / functions) Hit Total Coverage
Test: PostgreSQL 19devel Lines: 120 137 87.6 %
Date: 2025-07-27 12:18:32 Functions: 4 4 100.0 %
Legend: Lines: hit not hit

          Line data    Source code
       1             : /*
       2             :  *  pg_test_timing.c
       3             :  *      tests overhead of timing calls and their monotonicity:  that
       4             :  *      they always move forward
       5             :  */
       6             : 
       7             : #include "postgres_fe.h"
       8             : 
       9             : #include <limits.h>
      10             : 
      11             : #include "getopt_long.h"
      12             : #include "port/pg_bitutils.h"
      13             : #include "portability/instr_time.h"
      14             : 
      15             : static const char *progname;
      16             : 
      17             : static unsigned int test_duration = 3;
      18             : static double max_rprct = 99.99;
      19             : 
      20             : /* record duration in powers of 2 nanoseconds */
      21             : static long long int histogram[32];
      22             : 
      23             : /* record counts of first 10K durations directly */
      24             : #define NUM_DIRECT 10000
      25             : static long long int direct_histogram[NUM_DIRECT];
      26             : 
      27             : /* separately record highest observed duration */
      28             : static int32 largest_diff;
      29             : static long long int largest_diff_count;
      30             : 
      31             : 
      32             : static void handle_args(int argc, char *argv[]);
      33             : static uint64 test_timing(unsigned int duration);
      34             : static void output(uint64 loop_count);
      35             : 
      36             : int
      37          14 : main(int argc, char *argv[])
      38             : {
      39             :     uint64      loop_count;
      40             : 
      41          14 :     set_pglocale_pgservice(argv[0], PG_TEXTDOMAIN("pg_test_timing"));
      42          14 :     progname = get_progname(argv[0]);
      43             : 
      44          14 :     handle_args(argc, argv);
      45             : 
      46           2 :     loop_count = test_timing(test_duration);
      47             : 
      48           2 :     output(loop_count);
      49             : 
      50           2 :     return 0;
      51             : }
      52             : 
      53             : static void
      54          14 : handle_args(int argc, char *argv[])
      55             : {
      56             :     static struct option long_options[] = {
      57             :         {"duration", required_argument, NULL, 'd'},
      58             :         {"cutoff", required_argument, NULL, 'c'},
      59             :         {NULL, 0, NULL, 0}
      60             :     };
      61             : 
      62             :     int         option;         /* Command line option */
      63          14 :     int         optindex = 0;   /* used by getopt_long */
      64             :     unsigned long optval;       /* used for option parsing */
      65             :     char       *endptr;
      66             : 
      67          14 :     if (argc > 1)
      68             :     {
      69          14 :         if (strcmp(argv[1], "--help") == 0 || strcmp(argv[1], "-?") == 0)
      70             :         {
      71           2 :             printf(_("Usage: %s [-d DURATION] [-c CUTOFF]\n"), progname);
      72           2 :             exit(0);
      73             :         }
      74          12 :         if (strcmp(argv[1], "--version") == 0 || strcmp(argv[1], "-V") == 0)
      75             :         {
      76           2 :             puts("pg_test_timing (PostgreSQL) " PG_VERSION);
      77           2 :             exit(0);
      78             :         }
      79             :     }
      80             : 
      81          12 :     while ((option = getopt_long(argc, argv, "d:c:",
      82          12 :                                  long_options, &optindex)) != -1)
      83             :     {
      84          10 :         switch (option)
      85             :         {
      86           6 :             case 'd':
      87           6 :                 errno = 0;
      88           6 :                 optval = strtoul(optarg, &endptr, 10);
      89             : 
      90           6 :                 if (endptr == optarg || *endptr != '\0' ||
      91           4 :                     errno != 0 || optval != (unsigned int) optval)
      92             :                 {
      93           2 :                     fprintf(stderr, _("%s: invalid argument for option %s\n"),
      94             :                             progname, "--duration");
      95           2 :                     fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);
      96           2 :                     exit(1);
      97             :                 }
      98             : 
      99           4 :                 test_duration = (unsigned int) optval;
     100           4 :                 if (test_duration == 0)
     101             :                 {
     102           2 :                     fprintf(stderr, _("%s: %s must be in range %u..%u\n"),
     103             :                             progname, "--duration", 1, UINT_MAX);
     104           2 :                     exit(1);
     105             :                 }
     106           2 :                 break;
     107             : 
     108           2 :             case 'c':
     109           2 :                 errno = 0;
     110           2 :                 max_rprct = strtod(optarg, &endptr);
     111             : 
     112           2 :                 if (endptr == optarg || *endptr != '\0' || errno != 0)
     113             :                 {
     114           0 :                     fprintf(stderr, _("%s: invalid argument for option %s\n"),
     115             :                             progname, "--cutoff");
     116           0 :                     fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);
     117           0 :                     exit(1);
     118             :                 }
     119             : 
     120           2 :                 if (max_rprct < 0 || max_rprct > 100)
     121             :                 {
     122           2 :                     fprintf(stderr, _("%s: %s must be in range %u..%u\n"),
     123             :                             progname, "--cutoff", 0, 100);
     124           2 :                     exit(1);
     125             :                 }
     126           0 :                 break;
     127             : 
     128           2 :             default:
     129           2 :                 fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
     130             :                         progname);
     131           2 :                 exit(1);
     132             :                 break;
     133             :         }
     134             :     }
     135             : 
     136           2 :     if (argc > optind)
     137             :     {
     138           0 :         fprintf(stderr,
     139           0 :                 _("%s: too many command-line arguments (first is \"%s\")\n"),
     140           0 :                 progname, argv[optind]);
     141           0 :         fprintf(stderr, _("Try \"%s --help\" for more information.\n"),
     142             :                 progname);
     143           0 :         exit(1);
     144             :     }
     145             : 
     146           2 :     printf(ngettext("Testing timing overhead for %u second.\n",
     147             :                     "Testing timing overhead for %u seconds.\n",
     148             :                     test_duration),
     149             :            test_duration);
     150           2 : }
     151             : 
     152             : static uint64
     153           2 : test_timing(unsigned int duration)
     154             : {
     155             :     uint64      total_time;
     156           2 :     int64       time_elapsed = 0;
     157           2 :     uint64      loop_count = 0;
     158             :     uint64      prev,
     159             :                 cur;
     160             :     instr_time  start_time,
     161             :                 end_time,
     162             :                 temp;
     163             : 
     164             :     /*
     165             :      * Pre-zero the statistics data structures.  They're already zero by
     166             :      * default, but this helps bring them into processor cache and avoid
     167             :      * possible timing glitches due to COW behavior.
     168             :      */
     169           2 :     memset(direct_histogram, 0, sizeof(direct_histogram));
     170           2 :     memset(histogram, 0, sizeof(histogram));
     171           2 :     largest_diff = 0;
     172           2 :     largest_diff_count = 0;
     173             : 
     174           2 :     total_time = duration > 0 ? duration * INT64CONST(1000000000) : 0;
     175             : 
     176           2 :     INSTR_TIME_SET_CURRENT(start_time);
     177           2 :     cur = INSTR_TIME_GET_NANOSEC(start_time);
     178             : 
     179    47852634 :     while (time_elapsed < total_time)
     180             :     {
     181             :         int32       diff,
     182             :                     bits;
     183             : 
     184    47852632 :         prev = cur;
     185    47852632 :         INSTR_TIME_SET_CURRENT(temp);
     186    47852632 :         cur = INSTR_TIME_GET_NANOSEC(temp);
     187    47852632 :         diff = cur - prev;
     188             : 
     189             :         /* Did time go backwards? */
     190    47852632 :         if (unlikely(diff < 0))
     191             :         {
     192           0 :             fprintf(stderr, _("Detected clock going backwards in time.\n"));
     193           0 :             fprintf(stderr, _("Time warp: %d ms\n"), diff);
     194           0 :             exit(1);
     195             :         }
     196             : 
     197             :         /* What is the highest bit in the time diff? */
     198    47852632 :         if (diff > 0)
     199    47852632 :             bits = pg_leftmost_one_pos32(diff) + 1;
     200             :         else
     201           0 :             bits = 0;
     202             : 
     203             :         /* Update appropriate duration bucket */
     204    47852632 :         histogram[bits]++;
     205             : 
     206             :         /* Update direct histogram of time diffs */
     207    47852632 :         if (diff < NUM_DIRECT)
     208    47851888 :             direct_histogram[diff]++;
     209             : 
     210             :         /* Also track the largest observed duration, even if >= NUM_DIRECT */
     211    47852632 :         if (diff > largest_diff)
     212             :         {
     213           4 :             largest_diff = diff;
     214           4 :             largest_diff_count = 1;
     215             :         }
     216    47852628 :         else if (diff == largest_diff)
     217           0 :             largest_diff_count++;
     218             : 
     219    47852632 :         loop_count++;
     220    47852632 :         INSTR_TIME_SUBTRACT(temp, start_time);
     221    47852632 :         time_elapsed = INSTR_TIME_GET_NANOSEC(temp);
     222             :     }
     223             : 
     224           2 :     INSTR_TIME_SET_CURRENT(end_time);
     225             : 
     226           2 :     INSTR_TIME_SUBTRACT(end_time, start_time);
     227             : 
     228           2 :     printf(_("Average loop time including overhead: %0.2f ns\n"),
     229             :            INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count);
     230             : 
     231           2 :     return loop_count;
     232             : }
     233             : 
     234             : static void
     235           2 : output(uint64 loop_count)
     236             : {
     237           2 :     int         max_bit = 31;
     238           2 :     const char *header1 = _("<= ns");
     239           2 :     const char *header1b = _("ns");
     240           2 :     const char *header2 = /* xgettext:no-c-format */ _("% of total");
     241           2 :     const char *header3 = /* xgettext:no-c-format */ _("running %");
     242           2 :     const char *header4 = _("count");
     243           2 :     int         len1 = strlen(header1);
     244           2 :     int         len2 = strlen(header2);
     245           2 :     int         len3 = strlen(header3);
     246           2 :     int         len4 = strlen(header4);
     247             :     double      rprct;
     248           2 :     bool        stopped = false;
     249             : 
     250             :     /* find highest bit value */
     251          20 :     while (max_bit > 0 && histogram[max_bit] == 0)
     252          18 :         max_bit--;
     253             : 
     254             :     /* set minimum column widths */
     255           2 :     len1 = Max(8, len1);
     256           2 :     len2 = Max(10, len2);
     257           2 :     len3 = Max(10, len3);
     258           2 :     len4 = Max(10, len4);
     259             : 
     260           2 :     printf(_("Histogram of timing durations:\n"));
     261           2 :     printf("%*s   %*s %*s %*s\n",
     262             :            len1, header1,
     263             :            len2, header2,
     264             :            len3, header3,
     265             :            len4, header4);
     266             : 
     267           2 :     rprct = 0;
     268          48 :     for (int i = 0; i <= max_bit; i++)
     269             :     {
     270          46 :         double      prct = (double) histogram[i] * 100 / loop_count;
     271             : 
     272          46 :         rprct += prct;
     273          46 :         printf("%*ld   %*.4f %*.4f %*lld\n",
     274             :                len1, (1L << i) - 1,
     275             :                len2, prct,
     276             :                len3, rprct,
     277             :                len4, histogram[i]);
     278             :     }
     279             : 
     280           2 :     printf(_("\nObserved timing durations up to %.4f%%:\n"), max_rprct);
     281           2 :     printf("%*s   %*s %*s %*s\n",
     282             :            len1, header1b,
     283             :            len2, header2,
     284             :            len3, header3,
     285             :            len4, header4);
     286             : 
     287           2 :     rprct = 0;
     288       20002 :     for (int i = 0; i < NUM_DIRECT; i++)
     289             :     {
     290       20000 :         if (direct_histogram[i])
     291             :         {
     292        1518 :             double      prct = (double) direct_histogram[i] * 100 / loop_count;
     293        1518 :             bool        print_it = !stopped;
     294             : 
     295        1518 :             rprct += prct;
     296             : 
     297             :             /* if largest diff is < NUM_DIRECT, be sure we print it */
     298        1518 :             if (i == largest_diff)
     299             :             {
     300           0 :                 if (stopped)
     301           0 :                     printf("...\n");
     302           0 :                 print_it = true;
     303             :             }
     304             : 
     305        1518 :             if (print_it)
     306         424 :                 printf("%*d   %*.4f %*.4f %*lld\n",
     307             :                        len1, i,
     308             :                        len2, prct,
     309             :                        len3, rprct,
     310             :                        len4, direct_histogram[i]);
     311        1518 :             if (rprct >= max_rprct)
     312        1096 :                 stopped = true;
     313             :         }
     314             :     }
     315             : 
     316             :     /* print largest diff when it's outside the array range */
     317           2 :     if (largest_diff >= NUM_DIRECT)
     318             :     {
     319           2 :         double      prct = (double) largest_diff_count * 100 / loop_count;
     320             : 
     321           2 :         printf("...\n");
     322           2 :         printf("%*d   %*.4f %*.4f %*lld\n",
     323             :                len1, largest_diff,
     324             :                len2, prct,
     325             :                len3, 100.0,
     326             :                len4, largest_diff_count);
     327             :     }
     328           2 : }

Generated by: LCOV version 1.16