This is an archive of the discontinued LLVM Phabricator instance.

Add more information to the log timer dump

Authored by aadsm on Apr 27 2019, 11:09 PM.



The log timer dump is showing the time of the function itself minus any function that is called from this one that also happens to be timed. However, this is really not obvious and it also makes it hard to understand the time spent in total and also which children are actually taking the time.
To get a better reading of the timer dump I added the total, children (which I named child) and also the hit count. I used these timers to figure out a performance issue and only after adding this things were more clear to me.

It looks like this:

(lldb) log timer dump
35.447713617 sec (total: 35.449s; child: 0.001s; count: 1374) for void SymbolFileDWARF::Index()
29.717921481 sec (total: 29.718s; child: 0.000s; count: 8230500) for const lldb_private::ConstString &lldb_private::Mangled::GetDemangledName(lldb::LanguageType) const
21.049508865 sec (total: 24.683s; child: 3.633s; count: 1399) for void lldb_private::Symtab::InitNameIndexes()

Event Timeline

aadsm created this revision.Apr 27 2019, 11:09 PM
Herald added a project: Restricted Project. · View Herald TranscriptApr 27 2019, 11:09 PM

Could you provide a test? There are some existing tests for Timer in lldb/unittests/Utility/TimerTest.cpp which you can extend. You can run/compile these tests via LIT_FILTER="TimerTest" make check-lldb.

(I also believe this patch breaks TimerTest as it checks the output of DumpCategoryTimes)


Can you move struct this into an anonymous namespace?

teemperor requested changes to this revision.Apr 28 2019, 9:39 AM
This revision now requires changes to proceed.Apr 28 2019, 9:39 AM
aadsm updated this revision to Diff 197048.Apr 28 2019, 6:47 PM

Fix and add unit test

aadsm updated this revision to Diff 197049.Apr 28 2019, 6:51 PM

Move struct to anonymous namespace

aadsm marked an inline comment as done.Apr 28 2019, 6:59 PM
davide added a subscriber: davide.Apr 28 2019, 7:46 PM
davide added inline comments.

this seems ... very fragile.

aadsm marked an inline comment as done.Apr 28 2019, 8:16 PM
aadsm added inline comments.

that's a good point. I'm not that familiar with the ieee754 to know what's a safe interval here, do you know?

labath added a subscriber: labath.Apr 29 2019, 2:38 AM
labath added inline comments.

IIUC, one of these is redundant, as it can be recomputed from the other two, so we should remove it.


You can just move the const char * into the Stats struct and get rid of the std::pair. Then the CategoryMapIteratorSortCriterion thingy can also become a regular operator<.


I'm not sure this second line is really helpful here. Looking at this output, I would have never guessed that these numbers mean we were running two recursive timers belonging to the same category, and the entire thing finished in 20ms.

Maybe this isn't a real usage problem, as normally we don't have recursive timers (I believe), but in that case, we probably shouldn't have them in this test either (as right now it is the only documentation about how these times are supposed to work).

What's the reason for using recursive timers here? If you just wanted to check that the invocation count is 2, then you can wrap the two timers in {} blocks, so that they execute "sequentially" instead of recursively. (Which I guess would match the typical scenario where a timer-enabled function calls another timer-enabled function two times in a loop.)


Could you help clang-format split this string more reasonably (e.g., by manually splitting the string after the ])?


I think you want to use EXPECT_DOUBLE_EQ here.

aadsm planned changes to this revision.Apr 29 2019, 7:38 AM
aadsm marked 2 inline comments as done.
aadsm added inline comments.

ah yeah, that will be much better.


you're totally right, I actually didn't think much about it when I wrote the test but this should definitely be sequential not recursive.

aadsm marked an inline comment as done.Apr 29 2019, 11:56 AM
aadsm added inline comments.

It still doesn't help me :(

Expected: total1 - child1
      Which is: 0.099999999999999992
To be equal to: seconds1
      Which is: 0.10011115499999999
aadsm updated this revision to Diff 197246.Apr 29 2019, 7:13 PM

Only store needed data for dumping and put everything in the struct. Also fix tests to do sequential calls instead of recursive.

labath added inline comments.Apr 30 2019, 5:15 AM

Ah, ok I see now.. You need smaller precision because two of the numbers are only printed with three decimal spaces. In that case, you can do EXPECT_NEAR(a-b, c, 0.002). ( I chose 0.002 instead of 0.001 just in case it's possible for rounding errors to add up to over 0.001 --- cca. 0.0005 for a, ~0.0005 for b and ~0.0...05 for c).

aadsm updated this revision to Diff 197420.Apr 30 2019, 1:04 PM

Use EXPECT_NEAR for tests

labath accepted this revision.May 2 2019, 2:06 AM
aadsm updated this revision to Diff 198114.May 3 2019, 5:33 PM
  • Renamed CompareFileAndLine to FileAndLineEqual and made it return a bool
  • Made include_inlined_functions a mandatory parameter in GetSameLineContiguousAddressRange
  • Fix documentation
  • Refactored the object file creation from YAML
  • Got rid of a bunch of macros
  • Improved the test case
aadsm updated this revision to Diff 198116.May 3 2019, 5:36 PM

Undo the previous changes because I updated to the wrong diff.

aadsm updated this revision to Diff 201349.May 24 2019, 3:31 PM

Rebase and fixed an issue with one of the asserts.

xiaobai accepted this revision.May 29 2019, 9:19 AM
This revision was not accepted when it landed; it landed in state Needs Review.May 29 2019, 9:30 AM
This revision was automatically updated to reflect the committed changes.
Herald added a project: Restricted Project. · View Herald TranscriptMay 29 2019, 9:30 AM