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
Unknown Object (File)
Jan 28 2025, 3:59 AM
Unknown Object (File)
Jan 24 2025, 6:44 PM
Unknown Object (File)
Jan 17 2025, 7:35 PM
Unknown Object (File)
Jan 16 2025, 3:25 AM
Unknown Object (File)
Jan 15 2025, 11:04 PM
Unknown Object (File)
Jan 2 2025, 2:42 AM
Unknown Object (File)
Jan 1 2025, 2:01 AM
Unknown Object (File)
Jan 1 2025, 2:01 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
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.