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
F14303065: D19565.id.diff
Tue, Dec 17, 7:34 PM
Unknown Object (File)
Tue, Dec 17, 3:32 AM
Unknown Object (File)
Fri, Dec 6, 7:10 PM
Unknown Object (File)
Thu, Nov 28, 11:57 AM
Unknown Object (File)
Wed, Nov 27, 11:54 AM
Unknown Object (File)
Sat, Nov 23, 7:16 AM
Unknown Object (File)
Wed, Nov 20, 3:47 AM
Unknown Object (File)
Tue, Nov 19, 12:46 PM
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
Lint
Lint Not Applicable
Unit
Tests Not Applicable

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.