| Summary: | Excruciatingly slow loading of certain profiles | ||
|---|---|---|---|
| Product: | [Developer tools] kcachegrind | Reporter: | Szczepan Hołyszewski <rulatir> |
| Component: | general | Assignee: | Josef Weidendorfer <josef.weidendorfer> |
| Status: | RESOLVED NOT A BUG | ||
| Severity: | normal | ||
| Priority: | NOR | ||
| Version: | unspecified | ||
| Target Milestone: | --- | ||
| Platform: | Arch Linux | ||
| OS: | Linux | ||
| Latest Commit: | Version Fixed In: | ||
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. 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. Profiles seem to be loading quickly now, so it seems to be fixed one way or another. 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. 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. |
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.