Bug 420748 - Excruciatingly slow loading of certain profiles
Summary: Excruciatingly slow loading of certain profiles
Status: RESOLVED NOT A BUG
Alias: None
Product: kcachegrind
Classification: Developer tools
Component: general (show other bugs)
Version: unspecified
Platform: Arch Linux Linux
: NOR normal
Target Milestone: ---
Assignee: Josef Weidendorfer
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-04-29 11:25 UTC by Szczepan Hołyszewski
Modified: 2021-08-18 17:07 UTC (History)
0 users

See Also:
Latest Commit:
Version Fixed In:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Szczepan Hołyszewski 2020-04-29 11:25:43 UTC
FIRST THINGS FIRST

Please update kcachegrind version tags that are available for selection in this bug report form. The version I am reporting this bug again is 20.04.0, and the available versions are in their major zeros, so I am forced to select "unspecified".

SECOND THINGS SECOND

This is a complicated bug and I will be reporting several aspects of it in several places: kcachegrind, Xdebug, plasma, and whatever software artifact is responsible for consuming and processing stderr from programs launched from plasma desktop, either directly or via file association.

This happens to be the **first** of the places I am be reporting this, so references to other bug reports are absent from the initial report, and will be added in further comments.

STEPS TO REPRODUCE

1. Generate a large-ish (several tens of MB) profile with Xdebug
2. Have the profile file type associated with kcachegrind
3. Double click the profile file in Dolphin

OBSERVED RESULT

Kcachegrind starts and commences loading the profile, but loading is excruciatingly slow.

EXPECTED RESULT

Loading should be fast.

SOFTWARE/OS VERSIONS

Operating System: Arch Linux 
KDE Plasma Version: 5.18.4
KDE Frameworks Version: 5.69.0
Qt Version: 5.14.2
Kernel Version: 5.6.7-arch1-1
OS Type: 64-bit
Processors: 8 × AMD FX(tm)-8320 Eight-Core Processor
Memory: 15,6 GiB

ADDITIONAL INFORMATION

I have determined that the slowness is caused by large amount of stderr output produced by the kcachegrind process while loading the profile. The stderr output contains thousands of lines like this:

    Loading "/[REDACTED]/cachegrind.out.ccnb" : 11601339 :  "Garbage at end of call cost line ('-2664')"
    Loading "/[REDACTED]/cachegrind.out.ccnb" : 11601395 :  "Garbage at end of cost line ('-224')"
    Loading "/[REDACTED]/cachegrind.out.ccnb" : 11601403 :  "Garbage at end of call cost line ('-224')"
    Loading "/[REDACTED]/cachegrind.out.ccnb" : 11601491 :  "Garbage at end of call cost line ('-224')"
    Loading "/[REDACTED]/cachegrind.out.ccnb" : 11601559 :  "Garbage at end of cost line ('-320')"

It appears that whatever is consuming stderr from programs launched via a file association in plasma desktop, causes the process writing to stderr to block for cumulatively significant amounts of time, or slows the producer process down in some other way. This is definitely a problem on the consumer's end, and I would greatly appreciate someone knowledgeable to advise where I should report that problem.

This report however is about determining whether those "Garbage at end of( call)? cost line" messages are valid in the first place. I don't think they are. When I open the profile file in a text editor, I don't see any obvious "garbage" in there. I believe that these messages may be caused by a bug in kcachegrind.

This issue has been reported already in 2018 in Fedora bugtracker, but got closed due to EOL of the Fedora version it was reported against: https://bugzilla.redhat.com/show_bug.cgi?id=1537975

It may turn out that the profiles generated by Xdebug indeed contain garbage, in which case I will be reporting this against Xdebug.
Comment 1 Szczepan Hołyszewski 2020-04-29 11:37:50 UTC
Allright, it seems that Xdebug is indeed generating negative costs in some cases. Seems related to this: https://bugs.xdebug.org/view.php?id=357 (even though that one is reported against Windows and I am on Linux).

I would still appreciate an advice as to where I should report the stderr consumer slowness.
Comment 2 Szczepan Hołyszewski 2020-04-30 09:22:03 UTC
UPDATE: Xdebug's author explains that those negative costs are places where memory is freed. It is definitely part of the file format, and if kcachegrind cannot make sense of this, then it should silently ignore that field. Spamming stderr with warnings is definitely a defect.
Comment 3 Szczepan Hołyszewski 2021-07-10 16:01:07 UTC
Profiles seem to be loading quickly now, so it seems to be fixed one way or another.
Comment 4 Josef Weidendorfer 2021-08-09 09:18:01 UTC
Sorry, just saw that now.

It is certainly possible to hide such loading error messages
e.g. after 10 loading errors were detected. But then it makes sense
to just stop and tell the user that the file cannot be loaded due
to errors. Not sure this is wanted here.

For clarification: negative values definitely are not part of the
file format, because I designed the format and the format never changed
(this obviously was before XDebug ever could generate the format).
It simply makes no sense for cost metrics in a profiler to be negative.
Comment 5 Szczepan Hołyszewski 2021-08-18 17:07:39 UTC
I'll look into this again, but I seem to remember the XDebug guy explaining those weren't costs per se, but memory usage changes, which can be negative if a call ends up freeing more memory than it allocates.