diff --git a/cobc/ChangeLog b/cobc/ChangeLog index d6aaf4288..cbc77e792 100644 --- a/cobc/ChangeLog +++ b/cobc/ChangeLog @@ -1,12 +1,12 @@ 2023-09-04 Emilien Lemaire * parser.y: save the names of the procedures in global variables. - * parser.y: generate `cob_perf_enter` and `cob_perf_exit` calls when + * parser.y: generate `cob_prof_enter` and `cob_prof_exit` calls when needed - * flag.def: add `-fperf` to enable profiling + * flag.def: add `-fprof` to enable profiling * cobc.h: add a `cb_any_list` struct, a linked list with `void*` type data and global variables of this type, used for profiling - * typeck.c (emit_stop_run): add a call to `cob_perf_end` before the call + * typeck.c (emit_stop_run): add a call to `cob_prof_end` before the call to `cob_stop_run` * codegen.c: handle profiling code generation diff --git a/cobc/codegen.c b/cobc/codegen.c index 651165127..c9763643a 100644 --- a/cobc/codegen.c +++ b/cobc/codegen.c @@ -1793,7 +1793,7 @@ output_standard_includes (struct cb_program *prog) } } output_line ("#include "); - if (cb_flag_perf) output_line ("#include "); + if (cb_flag_prof) output_line ("#include "); output_newline (); } @@ -7875,11 +7875,11 @@ output_goto_1 (cb_tree x) output_move (cb_space, cb_debug_contents); } - if (cb_flag_perf) { + if (cb_flag_prof) { if (!!lb->section) { - output_line("cob_perf_goto(\"%s\", \"%s\");", lb->section->name, lb->name); + output_line("cob_prof_goto(\"%s\", \"%s\");", lb->section->name, lb->name); } else { - output_line("cob_perf_goto(NULL, \"%s\");", lb->name); + output_line("cob_prof_goto(NULL, \"%s\");", lb->name); } } output_line ("goto %s%d;", CB_PREFIX_LABEL, lb->id); @@ -12191,9 +12191,8 @@ output_internal_function (struct cb_program *prog, cb_tree parameter_list) /* Entry dispatch */ output_line ("/* Entry dispatch */"); - if (cb_flag_perf) { - output_line("cob_perf_init (total_times, paragraphs, paragraphs_count,\n" - " sections, sections_count,\n" + if (cb_flag_prof) { + output_line("cob_prof_init (total_times, sections, sections_count,\n" " para_per_sections, max_paragraphs_count);"); } if (cb_flag_stack_extended) { @@ -12284,8 +12283,8 @@ output_internal_function (struct cb_program *prog, cb_tree parameter_list) } } else { output_line ("/* Program exit */"); - if (cb_flag_perf) { - output_line("cob_perf_end ();"); + if (cb_flag_prof) { + output_line("cob_prof_end ();"); } output_newline (); if (needs_exit_prog) { @@ -13648,7 +13647,7 @@ max_length_section() { } static void -output_cob_perf_data () +output_cob_prof_data () { size_t paragraphs_count = 0; size_t sections_count = 0; @@ -13668,30 +13667,11 @@ output_cob_perf_data () } } - output_local ("/* cob_perf data */\n\n"); + output_local ("/* cob_prof data */\n\n"); output_local ("static size_t called_paragraphs[255];\n"); output_local ("static long start_times[255];\n"); output_local ("static long total_times[%lu][255] = {0};\n", paragraphs_count); - output_local ("static const char *paragraphs[] = {\n"); - { - struct cb_any_list *sl_p = sections_l; - struct cb_any_list *sn_p = sections_name; - while (!!sl_p && !!sn_p) { - struct cb_any_list *pl_p = (struct cb_any_list*)sl_p->data; - output_local(" \"%s\"", (char*)sn_p->data); - while (!!pl_p) { - output_local (",\n \"%s\"", (char*)pl_p->data); - pl_p = pl_p->next; - } - sl_p = sl_p->next; - sn_p = sn_p->next; - if (!!sl_p) output_local (",\n"); - } - output_local("};\n"); - } - output_local ("static size_t paragraphs_count = %lu;\n", paragraphs_count); - output_local ("static const char *sections[] = {\n"); { struct cb_any_list *sn_p = sections_name; @@ -13728,7 +13708,7 @@ output_cob_perf_data () output_local ("\n};\n"); } output_local ("static size_t max_paragraphs_count = %lu;\n\n", max); - output_local ("/* End of cob_perf data */\n"); + output_local ("/* End of cob_prof data */\n"); } void @@ -14007,7 +13987,7 @@ codegen_internal (struct cb_program *prog, const int subsequent_call) output_local_base_cache (); output_local_field_cache (prog); - if (cb_flag_perf) output_cob_perf_data (); + if (cb_flag_prof) output_cob_prof_data (); /* Report data fields */ if (prog->report_storage) { comment_gen = 0; diff --git a/cobc/flag.def b/cobc/flag.def index 790f28a4e..443a0c7f0 100644 --- a/cobc/flag.def +++ b/cobc/flag.def @@ -255,5 +255,5 @@ CB_FLAG_ON (cb_diagnostics_show_caret, 1, "diagnostics-show-caret", CB_FLAG_ON (cb_diagnostics_show_line_numbers, 1, "diagnostics-show-line-numbers", _(" -fno-diagnostics-show-line-numbers\tsuppress display of line numbers in diagnostics")) -CB_FLAG (cb_flag_perf, 1, "perf", - _(" -fperf enable profiling of the COBOL program")) +CB_FLAG (cb_flag_prof, 1, "prof", + _(" -fprof enable profiling of the COBOL program")) diff --git a/cobc/parser.y b/cobc/parser.y index 903ded442..b8db25dee 100644 --- a/cobc/parser.y +++ b/cobc/parser.y @@ -10949,10 +10949,10 @@ procedure_division: if (current_paragraph->exit_label) { emit_statement (current_paragraph->exit_label); } - if (cb_flag_perf) { + if (cb_flag_prof) { curr_para_name = cb_build_string (current_paragraph->name, strlen (current_paragraph->name)); curr_sec_name = cb_build_string (current_section->name, strlen (current_section->name)); - emit_statement (CB_BUILD_FUNCALL_2 ("cob_perf_exit_paragraph", curr_sec_name, curr_para_name)); + emit_statement (CB_BUILD_FUNCALL_2 ("cob_prof_exit_paragraph", curr_sec_name, curr_para_name)); } emit_statement (cb_build_perform_exit (current_paragraph)); } @@ -10960,11 +10960,11 @@ procedure_division: if (current_section->exit_label) { emit_statement (current_section->exit_label); } - if (cb_flag_perf) { + if (cb_flag_prof) { sections_l = cb_any_list_add (sections_l, (void*)paragraphs_l, 0); paragraphs_l = NULL; curr_sec_name = cb_build_string (current_section->name, strlen (current_section->name)); - emit_statement (CB_BUILD_FUNCALL_1 ("cob_perf_exit_section", curr_sec_name)); + emit_statement (CB_BUILD_FUNCALL_1 ("cob_prof_exit_section", curr_sec_name)); } emit_statement (cb_build_perform_exit (current_section)); } @@ -10992,7 +10992,7 @@ procedure_division: emit_statement (CB_TREE (current_section)); label = cb_build_reference ("MAIN PARAGRAPH"); current_paragraph = CB_LABEL (cb_build_label (label, NULL)); - if (cb_flag_perf) { + if (cb_flag_prof) { sections_name = cb_any_list_add (sections_name, (void*)"MAIN SECTION", 1); paragraphs_l = cb_any_list_add (paragraphs_l, (void*)"MAIN PARAGRAPH", 1); } @@ -11283,12 +11283,12 @@ _procedure_declaratives: if (current_paragraph->exit_label) { emit_statement (current_paragraph->exit_label); } - if (cb_flag_perf) { + if (cb_flag_prof) { sections_l = cb_any_list_add (sections_l, (void*)paragraphs_l, 0); paragraphs_l = NULL; curr_para_name = cb_build_string (current_paragraph->name, strlen (current_paragraph->name)); curr_sec_name = cb_build_string (current_section->name, strlen (current_section->name)); - emit_statement (CB_BUILD_FUNCALL_2 ("cob_perf_exit_paragraph", curr_sec_name, curr_para_name)); + emit_statement (CB_BUILD_FUNCALL_2 ("cob_prof_exit_paragraph", curr_sec_name, curr_para_name)); } emit_statement (cb_build_perform_exit (current_paragraph)); current_paragraph = NULL; @@ -11298,9 +11298,9 @@ _procedure_declaratives: emit_statement (current_section->exit_label); } current_section->flag_fatal_check = 1; - if (cb_flag_perf) { + if (cb_flag_prof) { curr_sec_name = cb_build_string (current_section->name, strlen (current_section->name)); - emit_statement (CB_BUILD_FUNCALL_1 ("cob_perf_exit_section", curr_sec_name)); + emit_statement (CB_BUILD_FUNCALL_1 ("cob_prof_exit_section", curr_sec_name)); } emit_statement (cb_build_perform_exit (current_section)); current_section = NULL; @@ -11381,10 +11381,10 @@ section_header: if (current_paragraph->exit_label) { emit_statement (current_paragraph->exit_label); } - if (cb_flag_perf) { + if (cb_flag_prof) { curr_para_name = cb_build_string (current_paragraph->name, strlen (current_paragraph->name)); curr_sec_name = cb_build_string (current_section->name, strlen (current_section->name)); - emit_statement (CB_BUILD_FUNCALL_2 ("cob_perf_exit_paragraph", curr_sec_name, curr_para_name)); + emit_statement (CB_BUILD_FUNCALL_2 ("cob_prof_exit_paragraph", curr_sec_name, curr_para_name)); } emit_statement (cb_build_perform_exit (current_paragraph)); } @@ -11392,11 +11392,11 @@ section_header: if (current_section->exit_label) { emit_statement (current_section->exit_label); } - if (cb_flag_perf) { + if (cb_flag_prof) { sections_l = cb_any_list_add (sections_l, (void*)paragraphs_l, 0); paragraphs_l = NULL; curr_sec_name = cb_build_string (current_section->name, strlen (current_section->name)); - emit_statement (CB_BUILD_FUNCALL_1 ("cob_perf_exit_section", curr_sec_name)); + emit_statement (CB_BUILD_FUNCALL_1 ("cob_prof_exit_section", curr_sec_name)); } emit_statement (cb_build_perform_exit (current_section)); } @@ -11411,7 +11411,7 @@ section_header: /* Begin a new section */ current_section = CB_LABEL (cb_build_label ($1, NULL)); - if (cb_flag_perf) + if (cb_flag_prof) sections_name = cb_any_list_add (sections_name, (void*)current_section->name, 1); current_section->flag_section = 1; /* Careful here, one negation */ @@ -11425,9 +11425,9 @@ section_header: { cb_tree curr_sec_name; emit_statement (CB_TREE (current_section)); - if (cb_flag_perf) { + if (cb_flag_prof) { curr_sec_name = cb_build_string (current_section->name, strlen(current_section->name)); - emit_statement (CB_BUILD_FUNCALL_1 ("cob_perf_enter_section", curr_sec_name)); + emit_statement (CB_BUILD_FUNCALL_1 ("cob_prof_enter_section", curr_sec_name)); } } ; @@ -11454,10 +11454,10 @@ paragraph_header: if (current_paragraph->exit_label) { emit_statement (current_paragraph->exit_label); } - if (cb_flag_perf) { + if (cb_flag_prof) { curr_para_name = cb_build_string (current_paragraph->name, strlen (current_paragraph->name)); curr_sec_name = cb_build_string (current_section->name, strlen (current_section->name)); - emit_statement (CB_BUILD_FUNCALL_2 ("cob_perf_exit_paragraph", curr_sec_name, curr_para_name)); + emit_statement (CB_BUILD_FUNCALL_2 ("cob_prof_exit_paragraph", curr_sec_name, curr_para_name)); } emit_statement (cb_build_perform_exit (current_paragraph)); if (current_program->flag_debugging && !in_debugging) { @@ -11478,10 +11478,10 @@ paragraph_header: current_section->flag_skip_label = !!skip_statements; current_section->xref.skip = 1; emit_statement (CB_TREE (current_section)); - if (cb_flag_perf) { + if (cb_flag_prof) { sections_name = cb_any_list_add (sections_name, (void*)"MAIN SECTION", 1); curr_sec_name = cb_build_string (current_section->name, strlen(current_section->name)); - emit_statement (CB_BUILD_FUNCALL_1 ("cob_perf_enter_section", curr_sec_name)); + emit_statement (CB_BUILD_FUNCALL_1 ("cob_prof_enter_section", curr_sec_name)); } } current_paragraph = CB_LABEL (cb_build_label ($1, current_section)); @@ -11490,11 +11490,11 @@ paragraph_header: current_paragraph->flag_real_label = !in_debugging; current_paragraph->segment = current_section->segment; emit_statement (CB_TREE (current_paragraph)); - if (cb_flag_perf) { + if (cb_flag_prof) { paragraphs_l = cb_any_list_add (paragraphs_l, (void*)current_paragraph->name, 1); curr_para_name = cb_build_string (current_paragraph->name, strlen(current_paragraph->name)); curr_sec_name = cb_build_string (current_section->name, strlen(current_section->name)); - emit_statement (CB_BUILD_FUNCALL_2 ("cob_perf_enter_paragraph", curr_sec_name, curr_para_name)); + emit_statement (CB_BUILD_FUNCALL_2 ("cob_prof_enter_paragraph", curr_sec_name, curr_para_name)); } } ; @@ -11601,9 +11601,9 @@ statements: current_section->flag_declaratives = !!in_declaratives; current_section->xref.skip = 1; emit_statement (CB_TREE (current_section)); - if (cb_flag_perf) { + if (cb_flag_prof) { curr_sec_name = cb_build_string (current_section->name, strlen(current_section->name)); - emit_statement (CB_BUILD_FUNCALL_1 ("cob_perf_enter_section", curr_sec_name)); + emit_statement (CB_BUILD_FUNCALL_1 ("cob_prof_enter_section", curr_sec_name)); } } if (!current_paragraph) { @@ -11618,11 +11618,11 @@ statements: current_paragraph->flag_dummy_paragraph = 1; current_paragraph->xref.skip = 1; emit_statement (CB_TREE (current_paragraph)); - if (cb_flag_perf) { + if (cb_flag_prof) { paragraphs_l = cb_any_list_add (paragraphs_l, (void*)"MAIN PARAGRAPH", 1); curr_para_name = cb_build_string (current_paragraph->name, strlen(current_paragraph->name)); curr_sec_name = cb_build_string (current_section->name, strlen(current_section->name)); - emit_statement (CB_BUILD_FUNCALL_2 ("cob_perf_enter_paragraph", curr_sec_name, curr_para_name)); + emit_statement (CB_BUILD_FUNCALL_2 ("cob_prof_enter_paragraph", curr_sec_name, curr_para_name)); } } if (check_headers_present (COBC_HD_PROCEDURE_DIVISION, 0, 0, 0) == 1) { diff --git a/cobc/typeck.c b/cobc/typeck.c index 96fe2d47a..8c1880617 100644 --- a/cobc/typeck.c +++ b/cobc/typeck.c @@ -14059,7 +14059,7 @@ cb_emit_start (cb_tree file, cb_tree op, cb_tree key, cb_tree keylen) void cb_emit_stop_run (cb_tree x) { - if (cb_flag_perf) cb_emit (CB_BUILD_FUNCALL_0 ("cob_perf_end")); + if (cb_flag_prof) cb_emit (CB_BUILD_FUNCALL_0 ("cob_prof_end")); cb_emit (CB_BUILD_FUNCALL_1 ("cob_stop_run", cb_build_cast_int (x))); } diff --git a/doc/ChangeLog b/doc/ChangeLog index 6370af4f0..77aded81c 100644 --- a/doc/ChangeLog +++ b/doc/ChangeLog @@ -1,3 +1,7 @@ +2023-09-07 Emilien Lemaire + + * gnucobol.texi: document the profiling feature + 2023-07-10 Simon Sobisch diff --git a/doc/gnucobol.texi b/doc/gnucobol.texi index a0ff783b6..2da1823a6 100644 --- a/doc/gnucobol.texi +++ b/doc/gnucobol.texi @@ -87,6 +87,7 @@ Welcome to the GnuCOBOL @value{VERSION} manual. * Customize:: Customizing the compiler * Optimize:: Optimizing your program * Debug:: Debugging your program +* Profiling:: Profiling your program * Extensions:: Non-standard extensions * System Routines:: Additional routines * Appendices:: List of supported features and options, @@ -155,6 +156,11 @@ Debug * Core Dumps:: Core Dumps * Trace:: Tracing execution +Profiling +* Profiling option:: Profiling options +* Profiling results:: Profiling results +* Profiling C interface:: C functions for profiling + Extensions * SELECT:: SELECT ASSIGN TO. @@ -1688,7 +1694,7 @@ machine. Set the config option @code{binary-byteorder} to In addition, setting the option @code{binary-size} to @code{2-4-8} or @code{1-2-4-8} is more efficient than others. -@node Debug, Extensions, Optimize, Top +@node Debug, Profiling, Optimize, Top @chapter Debug @menu @@ -1749,7 +1755,145 @@ Tracing program execution, either in general or in specific parts can be enabled @exampleindent 0 -@node Extensions, System Routines, Debug, Top +@node Profiling, Extensions, Debug, Top +@chapter Profiling COBOL +@cindex Profiling +@cindex Profiling your program + +@menu +* Profiling option:: Enabling profiling +* Profiling results:: Interpreting the results +* C interface:: Customize your profiling functions +@end menu + +@node Profiling option +@section @code{-fprof} flag +@cindex @code{-fprof} + +Profiling is enabled with the @code{-fprof} flag while compiling +your COBOL program. Then you can just execute your program and +a @code{prof.csv} or @code{prof.xlsx} file will be generated. + +@subsection Enabling xlsx result generation. + +The @code{prof.xlsx} file will be generated if when GnuCOBOL was compiled the +@code{libxlsxwritter} was found. If you do not want to generate the results +in xlsx format, and use csv instead, you can pass the @code{--with-xlsx=no} +to the @code{configure} script. + +@node Profiling results +@section Profiling results +@cindex Profiling results +@cindex How to interpret the profiling results + +The generated file, no matter its format, will have four columns: @code{Section}, +@code{Paragraph}, @code{Time (ns)}, @code{Explicit section time (ns)}. + +All the time values are in nanoseconds. + +The @code{Section} column contains the name of the section that is profiled. + +The @code{Paragraph} column contains the name of the paragraph that is profiled. + +The @code{Time (ns)} column contains the total time spend in each paragrpah, +either when it was executed by a @code{PERFORM}, a @code{GO TO}, or in the +normal flow of the program. For rows with only section name it is then +the sum of all the time spent in each of its paragraph. + +The @code{Explicit section time (ns)} column is the total time spent in +a section after a call to @code{PERFORM @var{section}} or +@code{GO TO @var{section}}. +A call to a paragraph in the section from another section is not counted +in this time. + +@subsection Consideration for @code{GO TO} + +When executing a @code{GO TO} that targets a section or a paragraph +outside of the current section, the profiler consider that you exited +every paragraphs and sections that were called before the @code{GO TO}. + +If the @code{GO TO} targets a paragraph inside the current section, +then all the previous paragraph are exited but not the current section. + +@node Profiling C interface +@section C interface for profiling +@cindex Profiling C interface +@cindex The C profiling functions + +The profiling functions are declared in 'libcob/cobprof.h' and defined in +'libcob/cobprof.c'. The interface has 7 exposed functions: +@table @code + +@item void cob_prof_init(long(*)[255], const char **, size_t, const char*(*)[255], size_t); + +@item void cob_prof_enter_paragraph(const char*, const char*); + +@item void cob_prof_exit_paragraph(const char*, const char*); + +@item void cob_prof_enter_section(const char*); + +@item void cob_prof_exit_section(const char*); + +@item void cob_prof_goto(const char*, const char*); + +@item void cob_prof_end(void); +@end table + +As these functions are declared as @code{extern}, you can override them with +your own functions. You will find below the documentation for each function +arguments and when they are called. + +@subsection @code{cob_prof_init} + +This function is executed before the first section of the program. The +arguments are given to avoid any allocation during the profiling of your +program, and correspond to the following values: + +@itemize @bullet + +@item @code{long(*)[255]}: This first argument is an 2 dimension array that +aims to contain the times spent in each section and pragraphs. +The first dimension correspond to the number of sections in the program +the second dimension is fixed at 255, and each index correspond to a paragraph +in the section. The index 254 of the second dimension is reserved for the +section time. + +@item @code{const char**, size_t}: These two arguments correspond to an array +containing all the names of the sections of the program, and the size of the +said array. + +@item @code{const char *(*)[255], size_t}: These two arguments correspond to an +array of paragraphs per section, the maximum number of paragraphs that can be found +for any section. +The index of each section correspond to the index of the name of this section +from the previous arguments. + +@end itemize + +@subsection @code{cob_prof_enter_paragraph} and @code{cob_prof_exit_paragraph} + +These two functions are executed before any code in each paragraph and when the +paragraph is explicitly or implicitly exited, respectively. + +The arguments of these functions are the name of the section containing the +paragraph and the name of the paragraph. + +@subsection @code{cob_prof_enter_section} and @code{cob_prof_exit_section} + +These two functions are executed before any code in each section and when the +section is explicitly or implicitly exited, respectively. + +The @code{enter} function is not executed when a paragraph is entered through +another section, but either when the section is explicitly called, or implicitly +when the section is the entry point of your program. + +The argument of each function correspond to the name of the section. + +@subsection @code{cob_perf_end} + +This function is executed just before the program ends and exits. It takes no argument. + +@node Extensions, System Routines, Profiling, Top @chapter Non-standard extensions @cindex Extensions @cindex Non-standard extensions diff --git a/libcob/ChangeLog b/libcob/ChangeLog index 3b9958837..7703aec11 100644 --- a/libcob/ChangeLog +++ b/libcob/ChangeLog @@ -1,9 +1,9 @@ 2023-09-04 Emilien Lemaire - * Makefile.am: add `cobperf.c` and `cobperf.h` in sources and headers - * cobperf.c, cobperf.h: implement profiling functions (time spent in each + * Makefile.am: add `cobprof.c` and `cobprof.h` in sources and headers + * cobprof.c, cobprof.h: implement profiling functions (time spent in each procedure of the program) - * common.c: include `cobperf.h` + * common.c: include `cobprof.h` 2023-07-28 Simon Sobisch diff --git a/libcob/Makefile.am b/libcob/Makefile.am index 5483f7247..751998d7a 100644 --- a/libcob/Makefile.am +++ b/libcob/Makefile.am @@ -22,7 +22,7 @@ lib_LTLIBRARIES = libcob.la libcob_la_SOURCES = common.c move.c numeric.c strings.c \ fileio.c call.c intrinsic.c termio.c screenio.c reportio.c cobgetopt.c \ - mlio.c coblocal.h cconv.c system.def cobperf.c + mlio.c coblocal.h cconv.c system.def cobprof.c if LOCAL_CJSON nodist_libcob_la_SOURCES = cJSON.c @@ -42,7 +42,7 @@ libcob_la_LDFLAGS = $(COB_FIX_LIBTOOL) -version-info 6:0:2 -no-undefined AM_LDFLAGS = $(COB_FIX_LIB) pkgincludedir = $(includedir)/libcob -pkginclude_HEADERS = common.h version.h cobgetopt.h cobperf.h \ +pkginclude_HEADERS = common.h version.h cobgetopt.h cobprof.h \ exception.def exception-io.def statement.def # Add rules for code-coverage testing, as provided by AX_CODE_COVERAGE diff --git a/libcob/cobperf.c b/libcob/cobprof.c similarity index 62% rename from libcob/cobperf.c rename to libcob/cobprof.c index 86eec0c14..9e7e78824 100644 --- a/libcob/cobperf.c +++ b/libcob/cobprof.c @@ -21,7 +21,7 @@ #define COB_LIB_EXPIMP #include "config.h" -#include "cobperf.h" +#include "cobprof.h" #include #include @@ -60,9 +60,18 @@ get_str_index(const char *str, const char **arr, size_t arr_len) return ULONG_MAX; } +static long +get_time(long start_time, struct timespec stop_time) { + // This allows to count the number of times a procedure is ran while testing the compiler + if (getenv ("COB_IS_RUNNING_IN_TESTMODE")) { + return 1; + } + + return stop_time.tv_nsec - start_time; +} + void -cob_perf_init(long (*total_times_p)[255], - const char **paragraphs_p, size_t paragraphs_count_p, +cob_prof_init(long (*total_times_p)[255], const char **sections_p, size_t sections_count_p, const char *(*para_per_sections_p)[255], size_t max_paragraphs_count_p) { @@ -71,7 +80,7 @@ cob_perf_init(long (*total_times_p)[255], if (max_paragraphs_count_p > 254) { fprintf (stderr, - "[cob_perf] Unable to handle more than 254 paragraphs per section" + "[cob_prof] Unable to handle more than 254 paragraphs per section" ", aborting profiling.\n"); return; @@ -94,7 +103,7 @@ cob_perf_init(long (*total_times_p)[255], } void -cob_perf_enter_paragraph(const char *section, const char *paragraph) +cob_prof_enter_paragraph(const char *section, const char *paragraph) { size_t sec_idx; size_t para_idx; @@ -107,14 +116,14 @@ cob_perf_enter_paragraph(const char *section, const char *paragraph) sec_idx = get_str_index (section, sections, sections_count); if (sec_idx == ULONG_MAX) { - fprintf (stderr, "[cob_perf] Could not find section %s, aborting profiling.\n", section); + fprintf (stderr, "[cob_prof] Could not find section %s, aborting profiling.\n", section); is_init = false; return; } para_idx = get_str_index (paragraph, para_per_sections[sec_idx], max_paragraphs_count); if (para_idx == ULONG_MAX) { - fprintf (stderr, "[cob_perf] Could not find paragraph %s IN %s, aborting profiling.\n", + fprintf (stderr, "[cob_prof] Could not find paragraph %s IN %s, aborting profiling.\n", section, paragraph); is_init = false; return; @@ -130,7 +139,7 @@ cob_perf_enter_paragraph(const char *section, const char *paragraph) } void -cob_perf_enter_section(const char *section) +cob_prof_enter_section(const char *section) { size_t sec_idx; struct timespec ts; @@ -139,7 +148,7 @@ cob_perf_enter_section(const char *section) sec_idx = get_str_index (section, sections, sections_count); if (sec_idx == ULONG_MAX) { - fprintf (stderr, "[cob_perf] Could not find section %s, aborting profiling.\n", section); + fprintf (stderr, "[cob_prof] Could not find section %s, aborting profiling.\n", section); is_init = false; return; } @@ -154,7 +163,7 @@ cob_perf_enter_section(const char *section) } void -cob_perf_exit_paragraph(const char *section, const char *paragraph) +cob_prof_exit_paragraph(const char *section, const char *paragraph) { size_t sec_idx; size_t para_idx; @@ -164,7 +173,7 @@ cob_perf_exit_paragraph(const char *section, const char *paragraph) sec_idx = get_str_index (section, sections, sections_count); if (sec_idx == ULONG_MAX) { - fprintf (stderr, "[cob_perf] Could not find section %s, aborting profiling.\n", section); + fprintf (stderr, "[cob_prof] Could not find section %s, aborting profiling.\n", section); is_init = false; return; } @@ -172,7 +181,7 @@ cob_perf_exit_paragraph(const char *section, const char *paragraph) para_idx = get_str_index (paragraph, para_per_sections[sec_idx], max_paragraphs_count); if (para_idx == ULONG_MAX) { - fprintf (stderr, "[cob_perf] Could not find paragraph %s IN %s, aborting profiling.\n", + fprintf (stderr, "[cob_prof] Could not find paragraph %s IN %s, aborting profiling.\n", section, paragraph); is_init = false; return; @@ -184,9 +193,9 @@ cob_perf_exit_paragraph(const char *section, const char *paragraph) size_t curr_sec = called_paragraphs[current_idx][0]; size_t curr_para = called_paragraphs[current_idx][1]; if (curr_para == ULONG_MAX) { - total_times[curr_sec][254] += ts.tv_nsec - start_times[current_idx]; + total_times[curr_sec][254] += get_time (start_times[current_idx], ts); } else { - total_times[curr_sec][curr_para] += ts.tv_nsec - start_times[current_idx]; + total_times[curr_sec][curr_para] += get_time (start_times[current_idx], ts); } current_idx--; if (curr_sec == sec_idx && curr_para == para_idx) return; @@ -194,7 +203,7 @@ cob_perf_exit_paragraph(const char *section, const char *paragraph) } void -cob_perf_exit_section(const char *section) +cob_prof_exit_section(const char *section) { size_t sec_idx; struct timespec ts; @@ -204,7 +213,7 @@ cob_perf_exit_section(const char *section) sec_idx = get_str_index (section, sections, sections_count); if (sec_idx == ULONG_MAX) { - fprintf (stderr, "[cob_perf] Could not find section %s, aborting profiling.\n", section); + fprintf (stderr, "[cob_prof] Could not find section %s, aborting profiling.\n", section); is_init = false; return; } @@ -218,9 +227,9 @@ cob_perf_exit_section(const char *section) if (curr_sec != sec_idx) return; // We exited all paragraphs entered in this section if (curr_para == ULONG_MAX) { - total_times[curr_sec][254] += ts.tv_nsec - start_times[current_idx]; + total_times[curr_sec][254] += get_time (start_times[current_idx], ts); } else { - total_times[curr_sec][curr_para] += ts.tv_nsec - start_times[current_idx]; + total_times[curr_sec][curr_para] += get_time (start_times[current_idx], ts); } current_idx--; if (curr_sec == sec_idx && curr_para == ULONG_MAX) { @@ -234,7 +243,7 @@ cob_perf_exit_section(const char *section) * We do not need to have a paragraph/section enter function since these will be executed when * the c goto is executed, just after the targeted label. */ void -cob_perf_goto(const char *section, const char *paragraph) +cob_prof_goto(const char *section, const char *paragraph) { size_t sec_idx; size_t para_idx; @@ -251,7 +260,7 @@ cob_perf_goto(const char *section, const char *paragraph) // GO TO section : section = NULL, paragraph = target section name while (current_idx != ULONG_MAX) { - cob_perf_exit_section (sections[called_paragraphs[current_idx][0]]); + cob_prof_exit_section (sections[called_paragraphs[current_idx][0]]); } return; @@ -260,7 +269,7 @@ cob_perf_goto(const char *section, const char *paragraph) sec_idx = get_str_index (section, sections, sections_count); if (sec_idx == ULONG_MAX) { - fprintf (stderr, "[cob_perf] Could not find section %s, aborting profiling.\n", section); + fprintf (stderr, "[cob_prof] Could not find section %s, aborting profiling.\n", section); is_init = false; return; } @@ -268,7 +277,7 @@ cob_perf_goto(const char *section, const char *paragraph) para_idx = get_str_index (paragraph, para_per_sections[sec_idx], max_paragraphs_count); if (para_idx == ULONG_MAX) { - fprintf (stderr, "[cob_perf] Could not find paragraph %s IN %s, aborting profiling\n", + fprintf (stderr, "[cob_prof] Could not find paragraph %s IN %s, aborting profiling\n", section, paragraph); is_init = false; return; @@ -278,14 +287,14 @@ cob_perf_goto(const char *section, const char *paragraph) size_t curr_para = called_paragraphs[current_idx][1]; while (curr_para != ULONG_MAX) { - cob_perf_exit_paragraph ( + cob_prof_exit_paragraph ( section, para_per_sections[sec_idx][called_paragraphs[current_idx][1]]); curr_para = called_paragraphs[current_idx][1]; } } else { while (current_idx != ULONG_MAX) { - cob_perf_exit_section (sections[called_paragraphs[current_idx][0]]); + cob_prof_exit_section (sections[called_paragraphs[current_idx][0]]); } } } @@ -304,7 +313,7 @@ size_t_len(size_t s) #endif void -cob_perf_end() +cob_prof_end() { #if WITH_XLSXWRITER @@ -316,83 +325,92 @@ cob_perf_end() size_t longest_para = 9; size_t longest_time = 9; size_t longest_perform = 26; -#else - FILE *file; #endif + FILE *file; + if (!is_init) return; while (current_idx != ULONG_MAX) { - cob_perf_exit_section (sections[called_paragraphs[current_idx][0]]); + cob_prof_exit_section (sections[called_paragraphs[current_idx][0]]); } #if WITH_XLSXWRITER - workbook = workbook_new ("perf.xlsx"); - worksheet = workbook_add_worksheet (workbook, NULL); - merge_format = workbook_add_format(workbook); - - format_set_align(merge_format, LXW_ALIGN_CENTER); - format_set_align(merge_format, LXW_ALIGN_VERTICAL_CENTER); - worksheet_write_string (worksheet, 0, 0, "Section", NULL); - worksheet_write_string (worksheet, 0, 1, "Paragraph", NULL); - worksheet_write_string (worksheet, 0, 2, "Time (ns)", NULL); - worksheet_write_string (worksheet, 0, 3, "Explicit section time (ns)", NULL); - - for (size_t i = 0; i < sections_count; i++) { - size_t curr_sec_row = row; - long total_sec_time = 0; - - worksheet_write_number (worksheet, row, 3, (double)total_times[i][254], NULL); - if (size_t_len (total_times[i][254]) > longest_time) longest_time = - size_t_len (total_times[i][254]); - row++; - - for (size_t j = 0; j < max_paragraphs_count; j++) { - const char *para = para_per_sections[i][j]; - if (para == NULL) break; - - if (longest_para < strlen (para)) longest_para = strlen (para); - total_sec_time += total_times[i][j]; - worksheet_write_string (worksheet, row, 1, para, NULL); - worksheet_write_number (worksheet, row, 2, (double)total_times[i][j], NULL); - if (size_t_len (total_times[i][j]) > longest_time) longest_time = - size_t_len (total_times[i][j]); - row++; - } - worksheet_write_number (worksheet, curr_sec_row, 2, total_sec_time, NULL); - worksheet_merge_range (worksheet, curr_sec_row, 0, row-1, 0, sections[i], merge_format); - if (strlen (sections[i]) > longest_sec) longest_sec = strlen (sections[i]); - if (size_t_len (total_sec_time) > longest_perform) longest_perform = - size_t_len (total_sec_time); - } + if (!getenv ("COB_IS_RUNNING_IN_TESTMODE")) { + workbook = workbook_new ("prof.xlsx"); + worksheet = workbook_add_worksheet (workbook, NULL); + merge_format = workbook_add_format(workbook); + + format_set_align(merge_format, LXW_ALIGN_CENTER); + format_set_align(merge_format, LXW_ALIGN_VERTICAL_CENTER); + worksheet_write_string (worksheet, 0, 0, "Section", NULL); + worksheet_write_string (worksheet, 0, 1, "Paragraph", NULL); + worksheet_write_string (worksheet, 0, 2, "Time (ns)", NULL); + worksheet_write_string (worksheet, 0, 3, "Explicit section time (ns)", NULL); - worksheet_set_column (worksheet, 0, 0, ((double)longest_sec) + 0.43, NULL); - worksheet_set_column (worksheet, 1, 1, ((double)longest_para) + 0.43, NULL); - worksheet_set_column (worksheet, 2, 2, ((double)longest_time) + 0.43, NULL); - worksheet_set_column (worksheet, 3, 3, ((double)longest_perform) + 0.43, NULL); - - workbook_close (workbook); - -#else - file = fopen ("prof.csv", "W"); - if (!!file) { - fprintf (file, "section,paragraph,time,PERFORM section time\n"); for (size_t i = 0; i < sections_count; i++) { + size_t curr_sec_row = row; long total_sec_time = 0; - fprintf (file, "%s, , , %lu ns\n", sections[i], total_times[i][254]); + + worksheet_write_number (worksheet, row, 3, (double)total_times[i][254], NULL); + if (size_t_len (total_times[i][254]) > longest_time) longest_time = + size_t_len (total_times[i][254]); + row++; for (size_t j = 0; j < max_paragraphs_count; j++) { const char *para = para_per_sections[i][j]; if (para == NULL) break; - fprintf (file, "%s, %lu ns\n", para, total_times[i][j]); + if (longest_para < strlen (para)) longest_para = strlen (para); total_sec_time += total_times[i][j]; + worksheet_write_string (worksheet, row, 1, para, NULL); + worksheet_write_number (worksheet, row, 2, (double)total_times[i][j], NULL); + if (size_t_len (total_times[i][j]) > longest_time) longest_time = + size_t_len (total_times[i][j]); + row++; } - fprintf (file, "%s, ,%lu ns, ", sections[i], total_sec_time); + worksheet_write_number (worksheet, curr_sec_row, 2, total_sec_time, NULL); + worksheet_merge_range (worksheet, curr_sec_row, 0, row-1, 0, sections[i], merge_format); + if (strlen (sections[i]) > longest_sec) longest_sec = strlen (sections[i]); + if (size_t_len (total_sec_time) > longest_perform) longest_perform = + size_t_len (total_sec_time); } - fclose (file); + worksheet_set_column (worksheet, 0, 0, ((double)longest_sec) + 0.43, NULL); + worksheet_set_column (worksheet, 1, 1, ((double)longest_para) + 0.43, NULL); + worksheet_set_column (worksheet, 2, 2, ((double)longest_time) + 0.43, NULL); + worksheet_set_column (worksheet, 3, 3, ((double)longest_perform) + 0.43, NULL); + + workbook_close (workbook); + } +#endif + +#if WITH_XLSXWRITER + if (getenv ("COB_IS_RUNNING_IN_TESTMODE")) { +#endif + file = fopen ("prof.csv", "w"); + if (!!file) { + fprintf (file, "section,paragraph,time,PERFORM section time\n"); + for (size_t i = 0; i < sections_count; i++) { + long total_sec_time = 0; + fprintf (file, "%s, , ,%lu ns\n", sections[i], total_times[i][254]); + + for (size_t j = 0; j < max_paragraphs_count; j++) { + const char *para = para_per_sections[i][j]; + if (para == NULL) break; + + fprintf (file, ",%s,%lu ns,\n", para, total_times[i][j]); + total_sec_time += total_times[i][j]; + } + fprintf (file, "%s, ,%lu ns,\n", sections[i], total_sec_time); + } + + fclose (file); + } else { + perror("Could not open file: prof.csv\n"); + } +#if WITH_XLSXWRITER } #endif diff --git a/libcob/cobperf.h b/libcob/cobprof.h similarity index 75% rename from libcob/cobperf.h rename to libcob/cobprof.h index dd8031441..6426c9087 100644 --- a/libcob/cobperf.h +++ b/libcob/cobprof.h @@ -18,8 +18,8 @@ along with GnuCOBOL. If not, see . */ -#ifndef cob_perf_h -#define cob_perf_h +#ifndef cob_prof_h +#define cob_prof_h #ifndef COB_EXT_EXPORT #if ((defined(_WIN32) || defined(__CYGWIN__)) && !defined(__clang__)) @@ -48,18 +48,17 @@ #include #include -COB_EXPIMP void cob_perf_init(long(*)[255], /* total_times */ - const char**, size_t, /* paragraphs */ +COB_EXPIMP void cob_prof_init(long(*)[255], /* total_times */ const char**, size_t, /* sections */ const char *(*)[255], size_t /* para_per_sections */); -COB_EXPIMP void cob_perf_enter_paragraph(const char*, const char*); -COB_EXPIMP void cob_perf_exit_paragraph(const char*, const char*); -COB_EXPIMP void cob_perf_enter_section(const char*); -COB_EXPIMP void cob_perf_exit_section(const char*); -COB_EXPIMP void cob_perf_goto(const char*, const char*); +COB_EXPIMP void cob_prof_enter_paragraph(const char*, const char*); +COB_EXPIMP void cob_prof_exit_paragraph(const char*, const char*); +COB_EXPIMP void cob_prof_enter_section(const char*); +COB_EXPIMP void cob_prof_exit_section(const char*); +COB_EXPIMP void cob_prof_goto(const char*, const char*); -COB_EXPIMP void cob_perf_end(void); +COB_EXPIMP void cob_prof_end(void); #endif diff --git a/libcob/common.c b/libcob/common.c index 9f0f9070b..c6007185a 100644 --- a/libcob/common.c +++ b/libcob/common.c @@ -18,7 +18,7 @@ along with GnuCOBOL. If not, see . */ -#include "cobperf.h" +#include "cobprof.h" #include "tarstamp.h" #include "config.h" @@ -3016,7 +3016,7 @@ call_exit_handlers_and_terminate (void) h = h->next; } } - cob_perf_end(); + cob_prof_end(); cob_terminate_routines (); } diff --git a/tests/ChangeLog b/tests/ChangeLog index aa1608f63..b8266d4a0 100644 --- a/tests/ChangeLog +++ b/tests/ChangeLog @@ -1,3 +1,7 @@ +2023-09-07 Emilien Lemaire + + * testsuite.src/used_binaries.at: add testing for profiling + 2023-07-10 Simon Sobisch diff --git a/tests/testsuite.src/used_binaries.at b/tests/testsuite.src/used_binaries.at index 03e6549d1..51bb792ad 100644 --- a/tests/testsuite.src/used_binaries.at +++ b/tests/testsuite.src/used_binaries.at @@ -1002,3 +1002,54 @@ AT_CHECK([$COBC -fdiagnostics-plain-output -fdiagnostics-show-caret -Wno-others AT_CLEANUP +AT_SETUP([run profiling]) +AT_KEYWORDS([cobc profiling]) + +AT_DATA([prog.cob], [ + IDENTIFICATION DIVISION. + PROGRAM-ID. prog. + PROCEDURE DIVISION. + 1ST SECTION. + PARA-0001. + PERFORM PARA-0003. + PARA-0002. + CONTINUE. + PARA-0003. + GO TO 2ND. + PARA-0004. + CONTINUE. + 2ND SECTION. + PARA-0005. + PERFORM PARA-0006. + PARA-0006. + CONTINUE. + PARA-0007. + STOP RUN. +]) + +AT_CAPTURE_FILE([prof.csv]) + +AT_CHECK([$COMPILE -fprof -x prog.cob], [0], [], [prog.cob: in section '1ST': +prog.cob: in paragraph 'PARA-0003': +prog.cob:11: warning: GO TO SECTION '2ND' +]) +AT_CHECK([./prog], [0], [], []) + +#note: The time here is actually the number of times the procedure has been run, to avoid +# any indeterminism in the running time of the procedure. +AT_CHECK([cat prof.csv], [0], [section,paragraph,time,PERFORM section time +1ST, , ,1 ns +,PARA-0001,1 ns, +,PARA-0002,0 ns, +,PARA-0003,1 ns, +,PARA-0004,0 ns, +1ST, ,2 ns, +2ND, , ,1 ns +,PARA-0005,1 ns, +,PARA-0006,2 ns, +,PARA-0007,1 ns, +2ND, ,4 ns, +], []) + +AT_CLEANUP +