Add a profiling tool in GnuCOBOL

[emilienlemaire]

This PR would add a simple profiling tool in GnuCOBOL which computes the time spent in each section and each paragraph of the COBOL program.

[codecov-commenter]

Codecov Report

Attention: Patch coverage is 86.81102% with 67 lines in your changes are missing coverage. Please review.

Project coverage is 66.06%. Comparing base (89c45a3) to head (67c02ad).

Files	Patch %	Lines
libcob/profiling.c	87.25%	21 Missing and 11 partials :warning:
libcob/common.c	64.77%	22 Missing and 9 partials :warning:
cobc/codegen.c	98.52%	0 Missing and 2 partials :warning:
cobc/parser.y	90.90%	1 Missing and 1 partial :warning:

:exclamation: Your organization needs to install the Codecov GitHub app to enable full functionality.

Additional details and impacted files

```diff @@ Coverage Diff @@ ## gcos4gnucobol-3.x #110 +/- ## ===================================================== + Coverage 65.87% 66.06% +0.19% ===================================================== Files 32 33 +1 Lines 59483 59947 +464 Branches 15709 15778 +69 ===================================================== + Hits 39182 39603 +421 - Misses 14282 14307 +25 - Partials 6019 6037 +18 ```

:umbrella: View full report in Codecov by Sentry.
:loudspeaker: Have feedback on the report? Share it here.

[emilienlemaire]

Thank you for the review. To answer your question, the xlsx support was implemented as I saw this was the standard output format of most proprietary COBOL profiling tools, as such I thought it would be a nice feature to add to this implementation. I have few things planned for this PR, mainly adding a flag to select between csv and xlsx if the latter is available, and the CALL profiling also, I just wanted some input on your side, hence the publication.

[GitMensch]

We commonly don't agree with proprietary COBOL compilers on many points, and as there is no real feature in that and people can open the csv in Excel - let's drop that format and the added checks, code and docs for the dependencies. If we see that there would be much benefit in it, then we can still add more formats later (but in this case that likely would be json [with the current JSON implementation as backend] and/or xml [with libxml2 as backend]).

Note that csv and json/xml are also much more preferable if you want to use the data in your test or even CI environment.

[lefessan]

people can open the csv in Excel - let's drop that format and the added checks, code and docs for the dependencies.

The choice is not between csv and xls, but to have both of them for different users: unix hackers will choose csv and use additional tools or scripts to extract data, but windows devs might prefer xls, because it is easier to view (csv always ask about the format to use to parse the file) and easier to graphically customize (adding colors to highlight the most important values, etc.). I think it would be better to have xls now, and then to drop it when powerful tools are available to post process csv files, rather than having only csv output now and never seeing such tools appear, or hard to find in the contribs...

[GitMensch]

Excel is also able to open Open Document Spreadsheeds (ods files), I'd be ok with adding this, but again - to reduce the complexity of the changes I suggest to split this into a second PR, one "just the feature", then another "adding a format which can be chosen by the user". Note: a simple ODS file is just minimal plain XML (can be created as text) named content.xml, put into an archive named ods. That doesn't even need any library (using zlib or similar to create the archive from memory instead of creating the xml text file up front would be useful (zlib I guess), but not mandatory (if not available a system call gzip would be executed).

[emilienlemaire]

Ok I will make this PR "feature only" with csv file generation only, and make another one later with ODS file format. The deletion of xlsx will come with the next commit, along with the other requested features / fixes

[GitMensch]

And, as a "general" thought: instead of resolving the "textual" data in libcob and storing it there, this part should likely be postponed until there's an actual write to the profiling file (when all the section/paragraph/location info can be requested/read). Switching to this approach should both save memory during collection and reduce the profiling overhead.

[GitMensch]

@lefessan If I understood this right, you're likely to take on this addition next, right?

[lefessan]

Yes, I have started fixing some of the issues you raised, but I still need some more time to get a better global picture of the patch before doing further changes.

[GitMensch]

Any chance on getting this done in the next two weeks? If not then we'll postpone it.

[lefessan]

Ok, I will do it or see if somebody else in the team can !

[lefessan]

I haven't tried it on a real-world example, as we don't have access to them in a "runnable way" (we have the code, but not the environment/databases needed to run them). Do you know some public project on Github that would make a good test for a real-world program ?

[GitMensch]

You could try ACAS from SourceForge. I don't know if it contains demo data, but you could contact its author and ask for that.

As a more complex example that does more reasonable work, try the later examples from worldcities (found in the examples in the GC contrib repo, you may want to mirror that to GitHub, too :-)

I may be able to give this a test in my employer's environment, but couldn't test many iterations, so we should postpone this after your initial tests are done... I take on the worldcities myself (you still can co-test that) to see the effect on CPU and time and to get an idea of the result file.

[GitMensch]

Note that checking the coverage shows that the branch coverage is < 60%

profiling.c			81.1 %	154 / 190	100.0 %	13 / 13	59.0 %	79 / 134

,.. but most of the non-covered branches would vanish if the memory is dynamically increased :-)

[GitMensch]

cobc -xg -fprof worldcities7.cbl commonroutines.cbl from https://sourceforge.net/p/gnucobol/contrib/HEAD/tree/trunk/samples/worldcities/ (with added assign to 'sort-file') results in

commonroutines.c: In function ‘printrunreport_’:
commonroutines.c:873:33: warning: implicit declaration of function ‘cob_prof_init’ [-Wimplicit-function-declaration]
  873 |   if (!prof_info) { prof_info = cob_prof_init ("printrunreport", procedures_names, 0); }
      |                                 ^~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:43:33: note: previous declaration of ‘cob_prof_init’ was here
   43 | COB_EXPIMP struct cobprof_info *cob_prof_init (
      |                                 ^~~~~~~~~~~~~
commonroutines.c:873:33: error: incompatible implicit declaration of function ‘cob_prof_init’
  873 |   if (!prof_info) { prof_info = cob_prof_init ("printrunreport", procedures_names, 0); }
      |                                 ^~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:43:33: note: previous implicit declaration of ‘cob_prof_init’ was here
   43 | COB_EXPIMP struct cobprof_info *cob_prof_init (
      |                                 ^~~~~~~~~~~~~
commonroutines.c:873:31: warning: assignment to ‘struct cobprof_info *’ from ‘int’ makes pointer from integer without a cast [-Wint-conversion]
  873 |   if (!prof_info) { prof_info = cob_prof_init ("printrunreport", procedures_names, 0); }
      |                               ^
commonroutines.c:883:3: warning: implicit declaration of function ‘cob_prof_enter_section’ [-Wimplicit-function-declaration]
  883 |   cob_prof_enter_section (prof_info, -1);
      |   ^~~~~~~~~~~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:52:17: note: previous declaration of ‘cob_prof_enter_section’ was here
   52 | COB_EXPIMP void cob_prof_enter_section  (struct cobprof_info *, int);
      |                 ^~~~~~~~~~~~~~~~~~~~~~
commonroutines.c:883:3: error: incompatible implicit declaration of function ‘cob_prof_enter_section’
  883 |   cob_prof_enter_section (prof_info, -1);
      |   ^~~~~~~~~~~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:52:17: note: previous implicit declaration of ‘cob_prof_enter_section’ was here
   52 | COB_EXPIMP void cob_prof_enter_section  (struct cobprof_info *, int);
      |                 ^~~~~~~~~~~~~~~~~~~~~~
commonroutines.c:889:3: warning: implicit declaration of function ‘cob_prof_enter_paragraph’ [-Wimplicit-function-declaration]
  889 |   cob_prof_enter_paragraph (prof_info, -1);
      |   ^~~~~~~~~~~~~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:50:17: note: previous declaration of ‘cob_prof_enter_paragraph’ was here
   50 | COB_EXPIMP void cob_prof_enter_paragraph (struct cobprof_info *, int);
      |                 ^~~~~~~~~~~~~~~~~~~~~~~~
commonroutines.c:889:3: error: incompatible implicit declaration of function ‘cob_prof_enter_paragraph’
  889 |   cob_prof_enter_paragraph (prof_info, -1);
      |   ^~~~~~~~~~~~~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:50:17: note: previous implicit declaration of ‘cob_prof_enter_paragraph’ was here
   50 | COB_EXPIMP void cob_prof_enter_paragraph (struct cobprof_info *, int);
      |                 ^~~~~~~~~~~~~~~~~~~~~~~~
commonroutines.c:1279:3: warning: implicit declaration of function ‘cob_prof_exit_paragraph’ [-Wimplicit-function-declaration]
 1279 |   cob_prof_exit_paragraph (prof_info, -1);
      |   ^~~~~~~~~~~~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:51:17: note: previous declaration of ‘cob_prof_exit_paragraph’ was here
   51 | COB_EXPIMP void cob_prof_exit_paragraph  (struct cobprof_info *, int);
      |                 ^~~~~~~~~~~~~~~~~~~~~~~
commonroutines.c:1279:3: error: incompatible implicit declaration of function ‘cob_prof_exit_paragraph’
 1279 |   cob_prof_exit_paragraph (prof_info, -1);
      |   ^~~~~~~~~~~~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:51:17: note: previous implicit declaration of ‘cob_prof_exit_paragraph’ was here
   51 | COB_EXPIMP void cob_prof_exit_paragraph  (struct cobprof_info *, int);
      |                 ^~~~~~~~~~~~~~~~~~~~~~~
commonroutines.c:1280:3: warning: implicit declaration of function ‘cob_prof_exit_section’ [-Wimplicit-function-declaration]
 1280 |   cob_prof_exit_section (prof_info, -1);
      |   ^~~~~~~~~~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:53:17: note: previous declaration of ‘cob_prof_exit_section’ was here
   53 | COB_EXPIMP void cob_prof_exit_section  (struct cobprof_info *, int);
      |                 ^~~~~~~~~~~~~~~~~~~~~
commonroutines.c:1280:3: error: incompatible implicit declaration of function ‘cob_prof_exit_section’
 1280 |   cob_prof_exit_section (prof_info, -1);
      |   ^~~~~~~~~~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:53:17: note: previous implicit declaration of ‘cob_prof_exit_section’ was here
   53 | COB_EXPIMP void cob_prof_exit_section  (struct cobprof_info *, int);
      |                 ^~~~~~~~~~~~~~~~~~~~~
commonroutines.c: In function ‘techtonics_’:
commonroutines.c:1624:33: error: incompatible implicit declaration of function ‘cob_prof_init’
 1624 |   if (!prof_info) { prof_info = cob_prof_init ("techtonics", procedures_names, 0); }
      |                                 ^~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:43:33: note: previous implicit declaration of ‘cob_prof_init’ was here
   43 | COB_EXPIMP struct cobprof_info *cob_prof_init (
      |                                 ^~~~~~~~~~~~~
commonroutines.c:1624:31: warning: assignment to ‘struct cobprof_info *’ from ‘int’ makes pointer from integer without a cast [-Wint-conversion]
 1624 |   if (!prof_info) { prof_info = cob_prof_init ("techtonics", procedures_names, 0); }
      |                               ^
commonroutines.c:1634:3: error: incompatible implicit declaration of function ‘cob_prof_enter_section’
 1634 |   cob_prof_enter_section (prof_info, -1);
      |   ^~~~~~~~~~~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:52:17: note: previous implicit declaration of ‘cob_prof_enter_section’ was here
   52 | COB_EXPIMP void cob_prof_enter_section  (struct cobprof_info *, int);
      |                 ^~~~~~~~~~~~~~~~~~~~~~
commonroutines.c:1640:3: error: incompatible implicit declaration of function ‘cob_prof_enter_paragraph’
 1640 |   cob_prof_enter_paragraph (prof_info, -1);
      |   ^~~~~~~~~~~~~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:50:17: note: previous implicit declaration of ‘cob_prof_enter_paragraph’ was here
   50 | COB_EXPIMP void cob_prof_enter_paragraph (struct cobprof_info *, int);
      |                 ^~~~~~~~~~~~~~~~~~~~~~~~
commonroutines.c:1736:3: error: incompatible implicit declaration of function ‘cob_prof_exit_paragraph’
 1736 |   cob_prof_exit_paragraph (prof_info, -1);
      |   ^~~~~~~~~~~~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:51:17: note: previous implicit declaration of ‘cob_prof_exit_paragraph’ was here
   51 | COB_EXPIMP void cob_prof_exit_paragraph  (struct cobprof_info *, int);
      |                 ^~~~~~~~~~~~~~~~~~~~~~~
commonroutines.c:1737:3: error: incompatible implicit declaration of function ‘cob_prof_exit_section’
 1737 |   cob_prof_exit_section (prof_info, -1);
      |   ^~~~~~~~~~~~~~~~~~~~~
In file included from commonroutines.c.l1.h:58,
                 from commonroutines.c:76:
/home/build/gnucobol-3.2-prof/libcob/cobprof.h:53:17: note: previous implicit declaration of ‘cob_prof_exit_section’ was here
   53 | COB_EXPIMP void cob_prof_exit_section  (struct cobprof_info *, int);
      |                 ^~~~~~~~~~~~~~~~~~~~~

Note: when adding a new option it is always good to locally run all tests with this option at least one time - in this case make checkall COBOL_FLAGS="-fprof", then check for errors and include failing samples - if any - to the testsuite.

I'm quite sure something will fail when the sample above doesn't compile (if not, then we have a problem in the testsuite).

[lefessan]

As a more complex example that does more reasonable work, try the later examples from worldcities (found in the examples in the GC contrib repo, you may want to mirror that to GitHub, too :-)

Do you mean like this one https://github.com/OCamlPro/gnucobol-contrib ?

[GitMensch]

As a more complex example that does more reasonable work, try the later examples from worldcities (found in the examples in the GC contrib repo, you may want to mirror that to GitHub, too :-)

Do you mean like this one https://github.com/OCamlPro/gnucobol-contrib ?

Exactly, so possibly check https://github.com/OCamlPro/gnucobol-contrib/blob/master/samples/prothsearch/prothsearch.cob (this will show that a CALL to non-COBOL should be seen in the profile, too) and https://github.com/OCamlPro/gnucobol-contrib/blob/master/samples/worldcities/worldcities8.cbl.

For a real world application, possibly have a look at https://sourceforge.net/projects/acas/.

[lefessan]

I will need some more time to fix some issues there are currently:

• use an integer comparison to identify in which section we are
• fix the counting of time to not count twice the time in case of recursion (i.e. a paragraph/section calling itself, either directly or indirectly)
• better understand if the section "direct" time is the same or not as the section "cumul" time

[GitMensch]

I suggest running the profiling with a Fibonacci program, possibly https://stackoverflow.com/a/75378982/5027456, to see how recursive program calls are handled. While we cannot use this specific program some recursive module should be included in the testsuite for the profiling code.

[lefessan]

@GitMensch I must be missing something obvious, but there is something I don't understand: if I run the testsuite with

COB_PROF_ENABLE=1 autofonce run

It looks like cobcrun does not see that COB_PROF_ENABLE=1. I have to set directly the default value of COB_PROF_ENABLE to "1" in common.c to get the expected behavior.

Is there something while running the testsuite that cleans the environment or something like that ?

[GitMensch]

The atlocal script normally sourced by the generated testsuite script drops all runtime settings, to ensure that the test run in a clean environment. If you want to enable it for everything temporarily adjust tests/atlocal.

[lefessan]

I moved a set of small changes to PR #126 to focus this PR only on profiling.

[GitMensch]

126

[lefessan]

Fix merged into #126

[lefessan]

Ok, I can fix these two things asap:

• remove info == NULL
• move the default file name to common.c (with the benefit that substitutions will be available for user-defined names too)

Otherwise, I think the PR is mergeable.

There is still another improvement that can be made: also measure time spent in CALLs. But it could be done in another PR once this one is merged.

About the merging process: the mirror shows no commit upstream for the last 6 months in any branch, is it a problem with the mirroring process (we had to switch servers a few weeks ago), or does it still correspond to the upstream state ?

[GitMensch]

Thanks for the note.

Yes, please do those adjustment.

Concerning the CALLs - that definitely would be good to measure (both amount and total time, as I think is the case in general), but I'm not sure how you'd include this in the output - one entry per CALL, I guess - which leaves the question if you want to additionally output the name, which would be reasonable because of CALL var-name. I agree that this can be done in a follow-up PR (it would be good to start on that, if you have the option; just create a new branch from the cleaned-up perf-line one).

The mirror seems to have an issue then - https://sourceforge.net/p/gnucobol/code/HEAD/log/?path=/branches shows the last commit (I plan to finish those this week btw) from August as GC 3.3-dev, but note that this is post-adjusted metadata the actual commit was done in December.

[lefessan]

The mirror seems to have an issue then - https://sourceforge.net/p/gnucobol/code/HEAD/log/?path=/branches shows the last commit (I plan to finish those this week btw) from August as GC 3.3-dev, but note that this is post-adjusted metadata the actual commit was done in December.

Yes, I noticed some activity, but I was not sure if it was not only the meta-data and not the content of the files. I tried to recover the mirroring system, but it might be that the metadata changes broke somegit2svn assumptions about the SVN history. Maybe it will be a good opportunity to re-extract a full history with correct links with Github users.

[GitMensch]

This reminds me of #67... Maybe an updated version of git2svn exists?

Note for the existing PRs the current state is fine.

[lefessan]

I have done the requested changes (removing info == NULL, moving the default to common.c, and fixing a bug where $b and $f are not expanded because the name of the executable was not known).

Now that commits have restarted landing in the SVN, can we start pushing all our SVN Ready branches to SVN ?

[lefessan]

I am not sure about what change is currently requested on this PR ?

[GitMensch]

I think that's fine and we'll adjust if/as necessary after getting it into svn.

[lefessan]

I added some tests on RECURSIVE. I put everything in syn_misc.at, since it was simpler to test both compilation and execution on the same programs instead of separately (that would require code duplication).

[GitMensch]

ping @lefessan - we do have some open review comments - once those are tackled this should get out; in any case that's already the "most comments issue" here :-)

[ddeclerck]

I think I tackled all the issues, except the syn_misc.at tests. Considering those new tests are unrelated to this PR, and because they raise questions (and possibly uncover bugs that must be fixed), I'd like to move them to a separate PR so as to no longer delay the profiling PR.

[GitMensch]

I think I tackled all the issues, except the syn_misc.at tests. Considering those new tests are unrelated to this PR, and because they raise questions (and possibly uncover bugs that must be fixed), I'd like to move them to a separate PR so as to no longer delay the profiling PR.

Agreed - can you please create a draft PR that contains everything that may seems questionable in the tests and is not "directly related", then push a new version of this PR that has those removed (and rebased)?

This should allow me to easily do a hopefully final review.

[ddeclerck]

Hi @GitMensch , Would this be okay to be merged now ?

[ddeclerck]

I think that's it ? If you're okay with the way I handled the change about relative-to-absolute path conversion.

[GitMensch]

That's fine, just add a changelog entry for the function extraction when doing the check-in "upstream".

For the test - I'd tend to have two AC_TEST and think 2>/dev/null is not needed for the first (is it?) and for the ls instead of >/dev/null we should use "ignore" for stdout.

[ddeclerck]

For the test - I'd tend to have two AC_TEST and think 2>/dev/null is not needed for the first (is it?)

Well, the runtime outputs File XXX generated to stderr when generating profiling infos. I can use ignore for that too instead of redierction.

[GitMensch]

closed as it is merged upstream (it would be good to update the git mirror of course, but that's a different thing.

[GitMensch]

checking common.h I've recognized that there is one change that should be applied here: the profiling types should be "anonymous" in common.h (then doesn't need more than typedef struct cob_prof_module cob_prof_module;) and only be defined in profiling.c because of encapsulation - we don't want them to be modified outside of profiling.c - see comment in https://github.com/OCamlPro/gnucobol/pull/137#discussion_r1578104214

@ddeclerck Sorry for not catching this beforehand - can you please adjust the code with a follow-up commit?

[GitMensch]

Sadly #140 was not pulled in before - the VC CI builds are broken since 23 days -as there is a new file and an adjustment to libcob/Makefile.am - but no changes to build_windows//libcob - can you please fix these (similar to r5112 - 8bc9fed39bb44d35907d9f0678ff09cd48b706bf) and change to use the anonymous type?

Oh - and while working on this - GCC says:

profiling.c: In function 'cob_prof_print_line':
profiling.c:449:41: warning: 'line' may be used uninitialized in this function [-Wmaybe-uninitialized]
  449 |                                         fprintf (file, "%d", line);
      |                                         ^~~~~~~~~~~~~~~~~~~~~~~~~~

so please check the paths (most times but not always gcc is right) and only if it is a false-positive initialize the variable to zero.

[GitMensch]

closed per follow-up PR "nearly checked in"