BryanDavis has uploaded a new change for review.
https://gerrit.wikimedia.org/r/119942
Change subject: Enable MWLogger logging for wfLogProfilingData
......................................................................
Enable MWLogger logging for wfLogProfilingData
Output structured profiling report data from wfLogProfilingData when
$wgUseMWLoggerForLegacyFunctions is enabled.
Requires Ie667944, I5c82299, and I1e5596d.
Change-Id: Iae11e1e4fe970ada74136f0e969dc624c586ce17
---
M includes/DefaultSettings.php
M includes/GlobalFunctions.php
M includes/profiler/Profiler.php
3 files changed, 87 insertions(+), 33 deletions(-)
git pull ssh://gerrit.wikimedia.org:29418/mediawiki/core
refs/changes/42/119942/1
diff --git a/includes/DefaultSettings.php b/includes/DefaultSettings.php
index 9653c9d..cb37f6e 100644
--- a/includes/DefaultSettings.php
+++ b/includes/DefaultSettings.php
@@ -5011,8 +5011,8 @@
* Feature switch to enable use of PSR-3 logger for legacy global logging
* functions.
*
- * When enabled wfDebug, wfDebugLog and wfLogDBError will route their log
- * events to MWLogger instances.
+ * When enabled wfDebug, wfDebugLog, wfLogDBError and wfLogProfilingData
+ * will route their log events to MWLogger instances.
*
* @since 1.23
*/
diff --git a/includes/GlobalFunctions.php b/includes/GlobalFunctions.php
index ef06d95..a511560 100644
--- a/includes/GlobalFunctions.php
+++ b/includes/GlobalFunctions.php
@@ -1265,7 +1265,7 @@
*/
function wfLogProfilingData() {
global $wgRequestTime, $wgDebugLogFile, $wgDebugRawPage, $wgRequest;
- global $wgProfileLimit, $wgUser;
+ global $wgProfileLimit, $wgUser, $wgUseMWLoggerForLegacyFunctions;
StatCounter::singleton()->flush();
@@ -1286,42 +1286,71 @@
$profiler->logData();
// Check whether this should be logged in the debug file.
- if ( $wgDebugLogFile == '' || ( !$wgDebugRawPage && wfIsDebugRawPage()
) ) {
+ if ( !wgUseMWLoggerForLegacyFunctions && (
+ $wgDebugLogFile == '' || ( !$wgDebugRawPage &&
wfIsDebugRawPage() ) ) ) {
return;
}
- $forward = '';
+ $ctx = array( 'elapsed' => $elapsed );
if ( !empty( $_SERVER['HTTP_X_FORWARDED_FOR'] ) ) {
- $forward = ' forwarded for ' . $_SERVER['HTTP_X_FORWARDED_FOR'];
+ $ctx['forwarded_for'] = $_SERVER['HTTP_X_FORWARDED_FOR'];
}
if ( !empty( $_SERVER['HTTP_CLIENT_IP'] ) ) {
- $forward .= ' client IP ' . $_SERVER['HTTP_CLIENT_IP'];
+ $ctx['client_ip'] = $_SERVER['HTTP_CLIENT_IP'];
}
if ( !empty( $_SERVER['HTTP_FROM'] ) ) {
- $forward .= ' from ' . $_SERVER['HTTP_FROM'];
+ $ctx['from'] = $_SERVER['HTTP_FROM'];
}
- if ( $forward ) {
- $forward = "\t(proxied via
{$_SERVER['REMOTE_ADDR']}{$forward})";
+ if ( isset( $ctx['forwarded_for'] ) ||
+ isset( $ctx['client_ip'] ) ||
+ isset( $ctx['from'] ) ) {
+ $ctx['proxy'] = $_SERVER['REMOTE_ADDR'];
}
+
// Don't load $wgUser at this late stage just for statistics purposes
- // @todo FIXME: We can detect some anons even if it is not loaded. See
User::getId()
+ // @todo FIXME: We can detect some anons even if it is not loaded.
+ // See User::getId()
if ( $wgUser->isItemLoaded( 'id' ) && $wgUser->isAnon() ) {
- $forward .= ' anon';
+ $ctx['anon'] = 'anon';
}
// Command line script uses a FauxRequest object which does not have
// any knowledge about an URL and throw an exception instead.
try {
- $requestUrl = $wgRequest->getRequestURL();
+ $ctx['url'] = urldecode( $wgRequest->getRequestURL() );
} catch ( MWException $e ) {
- $requestUrl = 'n/a';
+ $ctx['url'] = 'n/a';
}
- $log = sprintf( "%s\t%04.3f\t%s\n",
- gmdate( 'YmdHis' ), $elapsed,
- urldecode( $requestUrl . $forward ) );
+ if ( $wgUseMWLoggerForLegacyFunctions ) {
+ $log = MWLogger::getInstance( 'wfLogProfilingData' );
+ // NOTE: MWLogger output only supports function report logging
+ $raw = $profiler->getRawFunctionReport();
+ $log->info( 'Total: {total}', array_merge( $ctx, $raw ) );
- wfErrorLog( $log . $profiler->getOutput(), $wgDebugLogFile );
+ } else {
+ $forward = '';
+ if ( isset( $ctx['forwarded_for'] )) {
+ $forward = " forwarded for {$ctx['forwarded_for']}";
+ }
+ if ( isset( $ctx['client_ip'] ) ) {
+ $forward .= " client IP {$ctx['client_ip']}";
+ }
+ if ( isset( $ctx['from'] ) ) {
+ $forward .= " from {$ctx['from']}";
+ }
+ if ( $forward ) {
+ $forward = "\t(proxied via {$ctx['proxy']}{$forward})";
+ }
+ if ( isset( $ctx['anon'] ) ) {
+ $forward .= " {$ctx['anon']}";
+ }
+
+ $log = sprintf( "%s\t%04.3f\t%s%s\n",
+ gmdate( 'YmdHis' ), $elapsed, $ctx['url'], $forward );
+
+ wfErrorLog( $log . $profiler->getOutput(), $wgDebugLogFile );
+ }
}
/**
diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php
index a26ef68..604bb3c 100644
--- a/includes/profiler/Profiler.php
+++ b/includes/profiler/Profiler.php
@@ -575,11 +575,37 @@
/**
* Returns a list of profiled functions.
*
+ * @return Array
+ */
+ public function getRawFunctionReport() {
+ global $wgDebugFunctionEntry;
+ $wgDebugFunctionEntry = false;
+
+ $this->collateData();
+ $data = array();
+ $total = isset( $this->mCollated['-total'] ) ?
$this->mCollated['-total'] : 0;
+ foreach ( $this->mCollated as $fname => $elapsed ) {
+ $data[] = array(
+ 'fname' => $fname,
+ 'calls' => $this->mCalls[$fname],
+ 'total' => (float)( $elapsed * 1000 ),
+ 'each' => (float)( $elapsed * 1000 ) /
$this->mCalls[$fname],
+ 'percent' => $total ? 100. * $elapsed / $total
: 0,
+ 'memory' => $this->mMemory[$fname],
+ 'min' => $this->mMin[$fname] * 1000.0,
+ 'max' => $this->mMax[$fname] * 1000.0,
+ 'overhead' => $this->mOverhead[$fname],
+ );
+ }
+ return array( 'total' => $total, 'functions' => $data );
+ }
+
+ /**
+ * Returns a list of profiled functions.
+ *
* @return string
*/
function getFunctionReport() {
- $this->collateData();
-
$width = 140;
$nameWidth = $width - 65;
$format = "%-{$nameWidth}s %6d %13.3f %13.3f %13.3f%% %9d
(%13.3f -%13.3f) [%d]\n";
@@ -587,25 +613,24 @@
$prof = "\nProfiling data\n";
$prof .= sprintf( $titleFormat, 'Name', 'Calls', 'Total',
'Each', '%', 'Mem' );
- $total = isset( $this->mCollated['-total'] ) ?
$this->mCollated['-total'] : 0;
-
- foreach ( $this->mCollated as $fname => $elapsed ) {
+ $raw = $this->getRawFunctionReport();
+ foreach ( $raw['functions'] as $data ) {
$calls = $this->mCalls[$fname];
$percent = $total ? 100. * $elapsed / $total : 0;
$memory = $this->mMemory[$fname];
$prof .= sprintf( $format,
- substr( $fname, 0, $nameWidth ),
- $calls,
- (float)( $elapsed * 1000 ),
- (float)( $elapsed * 1000 ) / $calls,
- $percent,
- $memory,
- ( $this->mMin[$fname] * 1000.0 ),
- ( $this->mMax[$fname] * 1000.0 ),
- $this->mOverhead[$fname]
+ substr( $data['function'], 0, $nameWidth ),
+ $data['calls'],
+ $data['total'],
+ $data['each'],
+ $data['percent'],
+ $data['memory'],
+ $data['min'],
+ $data['max'],
+ $data['overhead']
);
}
- $prof .= "\nTotal: $total\n\n";
+ $prof .= "\nTotal: {$raw['total']}\n\n";
return $prof;
}
--
To view, visit https://gerrit.wikimedia.org/r/119942
To unsubscribe, visit https://gerrit.wikimedia.org/r/settings
Gerrit-MessageType: newchange
Gerrit-Change-Id: Iae11e1e4fe970ada74136f0e969dc624c586ce17
Gerrit-PatchSet: 1
Gerrit-Project: mediawiki/core
Gerrit-Branch: master
Gerrit-Owner: BryanDavis <[email protected]>
_______________________________________________
MediaWiki-commits mailing list
[email protected]
https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits
