Page MenuHomePhabricator

In "--trace" output, print elapsed miliseconds for ballparking performance issues
ClosedPublic

Authored by epriestley on Aug 3 2018, 10:09 PM.
Tags
None
Referenced Files
F13161046: D19565.diff
Mon, May 6, 4:44 AM
Unknown Object (File)
Fri, May 3, 10:09 AM
Unknown Object (File)
Mon, Apr 29, 3:29 AM
Unknown Object (File)
Thu, Apr 25, 3:41 AM
Unknown Object (File)
Fri, Apr 19, 7:51 PM
Unknown Object (File)
Thu, Apr 11, 10:50 AM
Unknown Object (File)
Apr 5 2024, 3:49 PM
Unknown Object (File)
Mar 2 2024, 7:34 AM
Subscribers
None

Details

Summary

Ref T13164. See PHI766. On PHI766, we saw a slow command on a production host with no ready access to XHProf / --xprofile.

We can reasonably turn --trace into a rough-cut profiler by adding milliseconds-since-start. Then --trace output is good enough to at least roughly ballpark where slowness is happening in many cases. This isn't as good as real profile and won't always be helpful, but at least some of the time it can at least give us enough information to know if, e.g., we should break out the profiler or not.

Test Plan

Ran bin/harbormaster rebuild-log --id ... --trace --force, got milliseconds-since-start in output and some vague idea about where time was being spent.

Diff Detail

Repository
rPHU libphutil
Branch
trace2
Lint
Lint Passed
Unit
Tests Passed
Build Status
Buildable 20572
Build 27945: Run Core Tests
Build 27944: arc lint + arc unit

Event Timeline

amckinley added inline comments.
src/serviceprofiler/PhutilServiceProfiler.php
200

I thought this should have been $elapsed / 1000, but now I've read the docs for microtime(true) and this is why I have trust issues.

This revision is now accepted and ready to land.Aug 3 2018, 10:56 PM
This revision was automatically updated to reflect the committed changes.