Add support for profiling interpreted code

[ChrisJefferson]

I noticed after a recent PR of Max's, it is now easy to add profiling of interpreted code.

This PR does that. I have benchmarked carefully and can't measure any more overhead -- this isn't surprising as the interpreter runs very little code (any function or loop is "coded", and then run as bytecode).

I export KERNEL_API_VERSION, because in the profiling package and debugging package I need to know if this PR happened. In profiling it just breaks testing, in debugging it breaks the package but I will release an updated version.

It might be the case we get some strange coverage out, I'm partly going to see what this PR produces, and compare with previous GAP.

[codecov]

Codecov Report

Merging #2772 into master will increase coverage by 7.55%.
The diff coverage is 68.83%.

@@             Coverage Diff             @@
##           master    #2772       +/-   ##
===========================================
+ Coverage    76.1%   83.65%    +7.55%     
===========================================
  Files         480      686      +206     
  Lines      240982   350857   +109875     
===========================================
+ Hits       183391   293523   +110132     
+ Misses      57591    57334      -257

Impacted Files	Coverage Δ
src/gapstate.h	71.42% <ø> (ø)	⬆️
src/modules.h	100% <ø> (ø)	⬆️
src/scanner.c	91.64% <100%> (+0.03%)	⬆️
src/gap.c	80.93% <100%> (-3.42%)	⬇️
src/io.c	58.3% <100%> (-0.33%)	⬇️
src/intrprtr.c	98.63% <100%> (ø)	⬆️
src/hookintrprtr.h	100% <100%> (ø)	⬆️
src/profile.c	44.47% <61.9%> (+3.26%)	⬆️
lib/package.gi	69.44% <0%> (-1.71%)	⬇️
... and 577 more

[ChrisJefferson]

Hmm.. this is hitting some lines it shouldn't. Investigating.

[fingolfin]

This looks sensible and useful overall!

But I am a bit surprised about the huge increase in coverage reported by codecov. Unfortunately, their PR specific pages like https://codecov.io/gh/gap-system/gap/pull/2772/ have been timing out for the past 1-2 weeks (and my support emails were answered with generic "we are looking into it, thank you for your patience" replies). So I can't see whether this is legitimate or a fluke w/o testing this manually right now.

So, not that I am mistrusting this code, but perhaps @ChrisJefferson could just confirm whether + 6.7% in coverage is legit?

[fingolfin]

change the comma to a semicolon or period? I was at first slightly confused by reading it like that.

[fingolfin]

Also, the corresponding GAPState member is named InterpreterStartLine -- why not name the two variables similarly? I find InterpreterStartLine much clearer than numberInterpreter.

[ChrisJefferson]

I named it numberInterpreter to line up with number (the previous variable), but I agree that's a silly name for a variable, and I shouldn't be carrying on it's usage :)

[fingolfin]

Off-topic: profileState_Active is not used outside this file anymore, as far as I can tell, so it could be moved back into struct ProfileState, couldn't it? (I am not suggesting you should do anything about this in this PR, just wondering while I am reading through this code again).
Also, there is no real reason why fopenMaybeCompressed and fcloseMaybeCompressed take struct ProfileState* ps as argument, instead of just accessing the profileState global directly, is there?

[ChrisJefferson]

The taking as an argument was beginning progress towards allowing multiple profilestates, so one could profile multiple threads in HPC-GAP, but it was never remotely finished. Should have a cleanup in this area, I agree.

[fingolfin]

Wouldn't it make more sense to check nameid==0 before calling outputFilenameIdIfRequired?

Ah, OK, I see it was like that before (and outputFilenameIdIfRequired does nothing if nameid is zero). Ah well,

[ChrisJefferson]

The +6.7 is legit, the reason for such high coverage becomes obvious if I cut+paste the longest files. None of these were covered before, as they are all executed in the interpreter. Things like conwdat3.g used to have 0 lines of code.

File	Coverage%	Executed Lines	Total Lines
/home/caj/files/reps/gap/gap/grp/clasmax.grp	99	24,760	24,764
/home/caj/files/reps/gap/gap/lib/conwdat3.g	100	20,572	20,572
/home/caj/files/reps/gap/gap/pkg/tomlib/data/tmm24.tom	100	16,573	16,573
/home/caj/files/reps/gap/gap/pkg/primgrp-3.3.1/data/gps2.g	100	13,428	13,428
/home/caj/files/reps/gap/gap/pkg/tomlib/data/tmlino.tom	100	13,043	13,043
/home/caj/files/reps/gap/gap/doc/ref/manual.six	100	13,035	13,035
/home/caj/files/reps/gap/gap/pkg/primgrp-3.3.1/data/gps8.g	100	11,268	11,268
/home/caj/files/reps/gap/gap/pkg/primgrp-3.3.1/data/gps3.g	100	9,948	9,948
/home/caj/files/reps/gap/gap/pkg/ctbllib/data/ctprimar.tbl	100	8,770	8,770
/home/caj/files/reps/gap/gap/pkg/primgrp-3.3.1/data/gps1.g	100	8,291	8,291
/home/caj/files/reps/gap/gap/pkg/tomlib/data/tmalt1.tom	100	8,046	8,046
/home/caj/files/reps/gap/gap/pkg/primgrp-3.3.1/lib/cohorts.grp	100	7,483	7,483
/home/caj/files/reps/gap/gap/pkg/cryst/grp/spacegrp.grp	100	4,132	4,132

[ChrisJefferson]

After further inspection, I've found a couple of places where coverage has got worse (mainly to do with lines containing things like a single else, which have been a problem in the past due to how they are parsed). I therefore would prefer to wait until we branch 4.10 (hopefully this week!), so there can be a full release cycle to tweak things back.

[fingolfin]

Ahh, I see, thanks for the explanation.

I agree that this should wait for GAP 4.11

Dually to this PR, what we are still lacking is a way to find unused .g / .gd / .gi files which have zero coverage because they are never read.

[fingolfin]

BTW, while browsing Codecov PR pages is still broken, one can inspect the commit at codecov to at least be able to browse through files and get their coverage. I.e.:
https://codecov.io/gh/gap-system/gap/tree/d06176adeefdc7210ce6e59e6182e625a945e6e0

Then one can use good old eyeballs to visually "diff" this against master.

(Note that https://codecov.io/gh/gap-system/gap also shows outdated information -- I sent a bugreport to Codecov about that earlier. Apparently, they don't show coverage the HEAD commit of master there, but rather they use the commit date to pick the commit/report to show... And as it happens, the last two PRs we "merged" via rebasing had older commit dates than the one before...)

[wilfwilson]

Hi @ChrisJefferson! This is cool. With the Semigroups and Digraphs packages, we use the profiling stuff in Travis to check the code coverage of our packages (we make sure that the coverage never falls below a certain level). When I test with this PR, a lot of the files have decreased coverage, to the point that Travis fails.

This seems to be solely due to more missed lines, including lines containing a single else, as you mention above, but there are also missed lines that include things like:

A temporary solution would be to reduce our required coverage for now, but it's not the nicest solution.

I can give you more specific details if you'd like.

[fingolfin]

@ChrisJefferson FYI, IntrIfEndBody does not use SKIP_IF_RETURNING() because that function has a non-void return value. So a INTERPRETER_PROFILE_HOOK(); may need to be inserted there. That's the only place like this, though.

[fingolfin]

BTW, InterpreterStartLine might be incorrect if there is a recursive interpreter call (right at its start, resp. right after it ended). So perhaps InterpreterStartLine should be stored and restored along with Symbol and other interpreter state. Unfortunately, that whole business of storing interpreter state is something I have not yet had time to clean up and refactor (though it is on my implicit TODO); as a result, Symbol is (re)stored via IO()->Input->symbol in io.c; while StackObj is (re)stored via PushPlist(STATE(IntrState), STATE(StackObj)); in intrprtr.c; and other bits and pieces are (re)stored via various code in read.c.

Anyway, that's hypothetical, I don't know whether this really manifests as a problem.

[ChrisJefferson]

I am saving/restoring in io.c, in the same place as Symbol is. I started thinking about trying to neaten this up, then got scared away, congratulations on your progress in cleaning up this area, it's very hairy :)

[ChrisJefferson]

Hi @wilfwilson , I believe I've cleared up those random elses, could you try again and see if things are improved? Thanks for the test case.

There is now only one problem I know about, which is (I believe) unfixable, but I will mention. Consider the following snippet, from algfp.gi:

line	code
381	InstallMethod( RelatorsOfFpAlgebra,
382	"for a full f.p. algebra",
383	true,
384	[ IsSubalgebraFpAlgebra and IsFullFpAlgebra ], 0,
385	A -> ElementsFamily( FamilyObj( A ) )!.relators );

In current master, line 385 is marked as "not executed", and everything else is not marked at all.

With this PR, all lines are marked as executed. That is because the closing bracket of line 385 is considered to "execute" the InstallMethod call, which makes line 385 marked as executed. Note that if that closing bracket is moved to a new line, then the function on line 385 is correctly marked as not executed.

Of course a future token-based profiler could handle these issues of multiple statements on a line.

[wilfwilson]

Hi @ChrisJefferson thanks for your changes. I haven't looked at everything in super close detail, but where I have looked I haven't seen any weird behaviour, and moreover, this does not seem to decrease the Semigroups package code coverage in the way that the previous version of this PR did. So: I'm happy for this to be merged whenever.

[fingolfin]

Actually, that last caveat, despite making perfect sense, also means that I now have serious reservations about this PR: There are tons of 1-line method installations like this in the kernel, and now we'd not be able anymore to tell if they get coverage or not...

But I am not quite willing to give up hope for that yet... I mean, sure, there is code like this, where we'll never be able to resolve this unless we stored profiling data token-based:

InstallMethod(NestingDepthM, [IsGF2MatrixRep], m->2);

But in the example we quote, couldn't we hack IntrFuncCallEnd to not emit coverage information? Granted, that might produce some lines which should get coverage but don't, but personally, I'd prefer that over lines which incorrectly are shown as covered. (I realize that this already happens, e.g. when people use multiple statements per line, but that's no reason to make it worse).

As to tokenization: I am not sure whether any profiling visualization tools support displaying data on a finer than per-line level. It sure would be cool if they did, though.

[ChrisJefferson]

So, with your suggestion it's easy to fix:

InstallMethod(NestingDepthM, [IsGF2MatrixRep], 
m->2);

Which is a fairly common pattern. The problem if it's all on one line is of course you parse and "execute" lots, include a list construction, grabbing a couple of identifiers, that kind of thing.

[fingolfin]

This needs to be incremented again, as the T_COPYING PR also increment this.

[ChrisJefferson]

I think this is now clean. I am in two minds about the whole "sneak something extra into SKIP_IF_IGNORING, I could go through and add an explicit PROFILE_HOOK() (or better name) to every occurrence of SKIP_IF_IGNORING, which wouldn't be much work but would make a 122-line patch.

[fingolfin]

Looks good to me.