793159 - Add more debug output to getLogExcerpt.php and other pre-fetching friends, using the new Debug class

Status: RESOLVED FIXED

(Tree Management Graveyard :: TBPL, defect)

Description

[Ed Morley [:emorley]]

To help with bug 790889 we should use the new Debug class from bug 793147 to add more detail to getLogExcerpt.php and friends' output.

Comment 1

[Ed Morley [:emorley]]

More logging has been added in other bugs - and the timeouts we most needed to solve have been fixed.

Think there isn't anything else that needs to be done here, given that we'll be focusing on TBPL2 from now on.

Comment 2

[Ed Morley [:emorley]]

Just found another patch in my queue that can be landed + a few extra changes I've just made to try and help determine why we're not getting bug suggestions for bug 840165.

Comment 3

[Ed Morley [:emorley]]

Attachment: Patch v1

Will test in Vagrant (once I get it set up again after the SSD replacement) before asking for review.

Comment 4

[Ed Morley [:emorley]]

Attachment: Patch v2

* Adds some additional log output lines to parts of the annotated summary generation. (These log lines appear in the import logs at https://tbpl-dev.allizom.org/cache/ and also when adding "&debug=1" to the URL eg: https://tbpl.mozilla.org/php/getLogExcerpt.php?type=annotated&id=19774648&regenerate=1&debug=1)
* Makes capitalisation on existing log entries more consistent.
* The change to getLogExcerpt.php is a no-op, since we end up including "inc/Debug.php" in AnnotatedSummaryGenerator.php anyway, so there's no point keeping it inside the conditional in getLogExcerpt.php, and the rest of the ordering change is just to tidy the file up by keeping the includes together.

Quick note about the debug logging - there are two ways:
1) Generic log entries (ie not timed), using the static[1] function: "Debug::output('Message');
2) Log entries that output both the message, and how long that step took to run (timed since that specific debug instance was created), eg: 
  $debug = new Debug();
  //stuff to be timed
  $debug->outputDuration('Message that will be shown next to duration');

[1] http://www.php.net/manual/en/language.oop5.static.php

Comment 5

[Ed Morley [:emorley]]

Ryan, would you be more comfortable (/be less of a squeeze on time sheriffing) if I redirected this review to someone else? :-)

Comment 6

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 714426 [details] [diff] [review]
Patch v2

Looks good, thanks for the detailed comments when you attached the patch. Answered the questions I had when looking it over. Sorry for the delay.

Comment 7

[Ed Morley [:emorley]]

No worries :-)

https://hg.mozilla.org/webtools/tbpl/rev/e27b160b36c6

Comment 8

[Ed Morley [:emorley]]

Looking good:

Prefetching: TB Rev3 Fedora 12 comm-central debug test xpcshell on aec7be06cf00
php /data/genericrhel6-dev/src/tbpl-dev.allizom.org/tbpl/dataimport/../php/getLogExcerpt.php id=20388722&type=annotated
Starting general_error log generation
Starting raw log generation
Generating raw log: 158ms
Generating general_error log: 241ms
Starting annotatedsummary log generation
Searching bugscache for "test_gmailAttributes.js": 2ms
Performing BzAPI lookup for "test_gmailAttributes.js": 556ms
Searching bugscache for "test_gmailAttributes.js": 3ms
Trying topFrame fallback on "mozalloc_abort(char const*)"
Searching bugscache for "mozalloc_abort(char const*)": 1ms
Generating annotatedsummary log: 610ms
Completed after 891ms

Prefetching: Ubuntu 12.04 x64 mozilla-inbound opt test xpcshell on 66006561df23
php /data/genericrhel6-dev/src/tbpl-dev.allizom.org/tbpl/dataimport/../php/getLogExcerpt.php id=20388744&type=annotated
Starting general_error log generation
Starting raw log generation
Generating raw log: 162ms
Generating general_error log: 244ms
Starting annotatedsummary log generation
Searching bugscache for "test_TelemetryTimestamps.js": 2ms
Searching bugscache for "test_TelemetryTimestamps.js": 2ms
Searching bugscache for "test_TelemetryTimestamps.js": 3ms
Searching bugscache for "test_provider_sessions.js": 3ms
Searching bugscache for "promise.js": 2ms
Searching bugscache for "11:59:22    ERROR - Return code: 1": 11ms
Performing BzAPI lookup for "11:59:22    ERROR - Return code: 1": 611ms
Generating annotatedsummary log: 679ms
Completed after 962ms

Comment 9

[Ed Morley [:emorley]]

In production :-)