Prepare the VM to profile itself with times and frequencies for all instructions - output in both Scheme and CSV formats. #530

jpellegrini · 2023-04-05T11:06:09Z

This recovers an old profiling functionality that used to be in vm.c. The previous version would count the frequencies of
instructions. The new code also measures the time taken by each instruction.

Instructions for using the profiler are added to vm.adoc. It is possible to dump the data to a CSV file, open in a spreadsheet and sort by total time taken by each instruction, or by average time per instruction...

CAVEAT: This only works for the USE_COMPUTED_GOTO compilation. For some reason, the standard code (without computed gotos) does not seem to be working (doesn't compile), even without this patch. See PR #528

A description follows.

The VM will, at the end of each iteration, check the instruction that was just executed and update:

The number of times that this instruction was executed
The number of times that this instruction was executed after the previous one (so it's possible to tell what pairs of instructions are more common)
The time taken to execute this instruction

This is done in the tick() C function (which is compiled conditionally on STAT_VM):

void tick(STk_instr b) {
  couple_instr[previous_op][b]++;
  cpt_inst[b]++;
  previous_op = b;

  current_time = clock();
  if (previous_time > 0)
      time_inst[b] += ((double)(current_time - previous_time)) / CLOCKS_PER_SEC;
  previous_time = current_time;
}

Two Scheme primitives are then available:

(%vm-dump-stats fname format) will dump the statistics to a file whose name is fname. This is NOT a Scheme port, but a Scheme string. The file will be open using plain fopen. When the format argument is the keyword :csv, then the output is in CSV format; otherwise, there will be one single S-expression in the file, readable from Scheme. This S-expression is an alist, documented in the file itself (see below).
(%vm-reset-stats) will reset all counters.

Here's the header from the Scheme version of a statistics dump:

;; STklos VM statistics. It can be read in Scheme, and it represents one single
;; object: an alist with the names of instructions, and each CDR is a list containing:
;;
;; * count (the number of times this instruction was executed)
;; * time (the total time the program spent on this instruction)
;; * avg time (the average number of time spent on each execution of this instruction)
;; * an alist containing, for each OTHER instruction, the number of times they appeared\n"
;;   together in the code.
;;
;; ( (INS1 count1 time1 avgtime1 ( (INS1 . count1) (INS2 . count2) ... (INSn  .countn)))
;;   (INS2 count2 time2 avgtime2 ( (INS1 . count1) (INS2 . count2) ... (INSn  .countn)))
;;   ...
;;   (INS2 countk timek avgtimek ( (INS1 . count1) (INS2 . count2) ... (INSn  .countn))) )

The C code for printing the instructions is in the functions dump_couple_instr_csv and dump_couple_instr_scm.

jpellegrini · 2023-04-05T13:37:30Z

I added a profiling macro...

(%with-profile-data "file-name.csv" :csv
  (display a)
  (newline)
  (values 1 2 3))

This will write the profiling data to file-name.csv, and will return the same values that the code would (1, 2, 3).
The expansion is

(receive
  result-4
  (begin (%vm-reset-stats)
         (display a)
         (newline)
         (values 1 2 3))
  (begin (%vm-dump-stats "file-name.csv" #:csv)
         (apply values result-4)))

Also, since this macro needs to know if the stats code is available, we also include a primitive, (%vm-has-stats).

When the stats code is not compiled in, the macro just expands to (begin ...code...).

It is still marked with %, but I suppose this could be useful for the general user in the future?

jpellegrini · 2023-04-05T15:57:59Z

And just for completness...

(%vm-collecting-stats?) returns true when the system is collecting statistics
(that is, whenthe variable collect_stats is one), and false otherwise.
(%vm-collect-stats-start) and (%vm-collect-stats-stop) wil turn collecting on
and off, respectively.

Collecting statistics is off by default, especially because compiling STklos is very slow with statistics gathering. It should be turned on before profiling.

The status of "collecting" or "not collecting" reflects what happens internally in the statistics gathering code, when it is compiled in. If STklos was compiled without STAT_VM, then those procedures are just not available at all.

jpellegrini · 2023-04-05T16:36:38Z

It only measures the times for VM instructions. However, for example...I have a benchmark in which UGREF_INVOKE takes a lot of time. But it's not, itself, slow. It happens to send the control flow to FUNCALL, which I think is the slow part of it. So maybe we could also measure, besides instructions, some specific parts of the VM (like FUNCALL?)

jpellegrini · 2023-04-05T20:16:40Z

I have written tick() as a nested function, but that's a GNU extension. I'll fix it

jpellegrini · 2023-04-05T21:28:52Z

@egallesio I think I have the statistics collection working (for the computed goto version), but I have one question...

These are declared static in vm.c:

static int couple_instr[NB_VM_INSTR][NB_VM_INSTR];
static int cpt_inst[NB_VM_INSTR];
static double time_inst[NB_VM_INSTR];

but then, wouldn't several threads clobber the data being collected by each other? (For example, in the couple_instr matrix one thread would overwrite the previous instruction from the other, and the data wouldn't correspond to wha tactually happens) -- right? Should we move these to inside run_vm()? Or something else?

jpellegrini · 2023-07-09T15:41:14Z

Hi @egallesio !
If #561 is merged, I'll update this one (which will be necessary, I think).

jpellegrini · 2023-07-10T15:38:15Z

I'm making adjustments to this one, as it would currently do the wrong thing, depending on the use of computed gotos.

jpellegrini · 2023-07-10T16:22:27Z

OK @egallesio I think this one is ready now! :)

This recovers an old profiling functionality that used to be in `vm.c`. The previous version would count the frequencies of instructions. The new code also measures the time taken by each instruction. A description follows. The VM will, at the end of each iteration, check the instruction that was just executed and update: * The number of times that this instruction was executed * The number of times that this instruction was executed after the previous one (so it's possible to tell what pairs of instructions are more common) * The time taken to execute this instruction This is done in the `tick()` C function (which is compiled conditionally on `STAT_VM`): ``` void tick(STk_instr b) { couple_instr[previous_op][b]++; cpt_inst[b]++; previous_op = b; current_time = clock(); if (previous_time > 0) time_inst[b] += ((double)(current_time - previous_time)) / CLOCKS_PER_SEC; previous_time = current_time; } ``` Two Scheme primitives are then available: * `(%vm-dump-stats fname format)` will dump the statistics to a file whose name is `fname`. This is *NOT* a Scheme port, but a Scheme string. The file will be open using plain `fopen`. When the `format` argument is the keyword `:csv`, then the output is in CSV format; otherwise, there will be one single S-expression in the file, readable from Scheme. This S-expression is an alist, documented in the file itself (see below). * `%vm-reset-stats` will reset all counters. The documentation for the Scheme format for the dumped instructions is shown below. ``` ;; STklos VM statistics. It can be read in Scheme, and it represents one single ;; object: an alist with the names of instructions, and each CDR is a list containing: ;; ;; * count (the number of times this instruction was executed) ;; * time (the total time the program spent on this instruction) ;; * avg time (the average number of time spent on each execution of this instruction) ;; * an alist containing, for each OTHER instruction, the number of times they appeared\n" ;; together in the code. ;; ;; ( (INS1 count1 time1 avgtime1 ( (INS1 . count1) (INS2 . count2) ... (INSn .countn))) ;; (INS2 count2 time2 avgtime2 ( (INS1 . count1) (INS2 . count2) ... (INSn .countn))) ;; ... ;; (INS2 countk timek avgtimek ( (INS1 . count1) (INS2 . count2) ... (INSn .countn))) ) ``` The C code for printing the instructions is in the functions `dump_couple_instr_csv` and `dump_couple_instr_scm`.

`(%with-profile-data filename [ format ] body)` will profile a specific piece of code. It returns the same values that the code would return. Also, since this macro needs to know if the stats code is available, we also include a primitive, `(%vm-has-stats)`.

* `(%vm-collecting-stats?)` returns true when the system is collecting statistics (that is, whenthe variable `collect_stats` is one), and false otherwise. * `(%vm-collect-stats-start)` and `(%vm-collect-stats-stop)` wil turn collecting on and off, respectively.

by excluding the collecting code itself from the timing.

And some other adjustments.

egallesio · 2024-07-20T16:42:47Z

After 15 months, I have finally merged this great PR 😄

I have applied small modifications (replaced the 3 functions around getting and setting the stats or not) by a unique parameter. I have also suppressed the primitive (%vm-has-stats) since it can be easily determined from the new version of (%vm-config) in PR #560

Finally, macro %with-profile-data is only defined when STklos is compiled with the STAT_VM flag set.

jpellegrini mentioned this pull request Apr 5, 2023

STklos seems to only compile with USE_COMPUTED_GOTO #528

Closed

jpellegrini force-pushed the stat branch 2 times, most recently from ca16c54 to 0d52abc Compare April 5, 2023 11:46

jpellegrini force-pushed the stat branch from ba5dd9d to 6e05efb Compare April 5, 2023 13:52

jpellegrini force-pushed the stat branch from e4e871c to 51e503d Compare April 12, 2023 16:20

jpellegrini force-pushed the stat branch from 51e503d to bb3f78b Compare July 10, 2023 16:22

jpellegrini added 7 commits November 20, 2023 15:59

Add documentation for VM profiler

cdb2490

Add a profiling macro

50c9ad1

`(%with-profile-data filename [ format ] body)` will profile a specific piece of code. It returns the same values that the code would return. Also, since this macro needs to know if the stats code is available, we also include a primitive, `(%vm-has-stats)`.

Make stats collecting a bit more precise

cc199ac

by excluding the collecting code itself from the timing.

Typos and editorial fixes

89fee0c

Get tick() outside of run_vm() !

5581ad8

And some other adjustments.

jpellegrini force-pushed the stat branch from bb3f78b to 5581ad8 Compare November 20, 2023 19:00

jpellegrini added 2 commits March 24, 2024 09:27

Merge branch 'master' into stat

9914924

Merge branch 'egallesio:master' into stat

0638c88

egallesio merged commit bff475f into egallesio:master Jul 20, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Prepare the VM to profile itself with times and frequencies for all instructions - output in both Scheme and CSV formats. #530

Prepare the VM to profile itself with times and frequencies for all instructions - output in both Scheme and CSV formats. #530

jpellegrini commented Apr 5, 2023 •

edited

Loading

jpellegrini commented Apr 5, 2023 •

edited

Loading

jpellegrini commented Apr 5, 2023

jpellegrini commented Apr 5, 2023

jpellegrini commented Apr 5, 2023

jpellegrini commented Apr 5, 2023

jpellegrini commented Jul 9, 2023

jpellegrini commented Jul 10, 2023

jpellegrini commented Jul 10, 2023

egallesio commented Jul 20, 2024

Prepare the VM to profile itself with times and frequencies for all instructions - output in both Scheme and CSV formats. #530

Prepare the VM to profile itself with times and frequencies for all instructions - output in both Scheme and CSV formats. #530

Conversation

jpellegrini commented Apr 5, 2023 • edited Loading

jpellegrini commented Apr 5, 2023 • edited Loading

jpellegrini commented Apr 5, 2023

jpellegrini commented Apr 5, 2023

jpellegrini commented Apr 5, 2023

jpellegrini commented Apr 5, 2023

jpellegrini commented Jul 9, 2023

jpellegrini commented Jul 10, 2023

jpellegrini commented Jul 10, 2023

egallesio commented Jul 20, 2024

jpellegrini commented Apr 5, 2023 •

edited

Loading

jpellegrini commented Apr 5, 2023 •

edited

Loading