From: Ori Livneh Date: Mon, 6 Jan 2014 21:24:44 +0000 (-0800) Subject: Add ProfilerMwprof X-Git-Tag: 1.31.0-rc.0~17349^2 X-Git-Url: http://git.cyclocoop.org/%22%20.%20generer_url_ecrire%28%22suivi_revisions%22%29%20.%20%22?a=commitdiff_plain;h=c5e6ce0f9e4d593a4cb8c58e7da4a3b3477c4e5c;p=lhc%2Fweb%2Fwiklou.git Add ProfilerMwprof ProfilerMwprof is similar to ProfilerSimpleUDP in that accumulated profiling samples are emitted to a remote host using UDP. Profiling data for sections that are called multiple times are aggregating using the RunningStat class I introduced in Ifedda276d; this provides the ability to compute timing variance across multiple requests without storing individual values for a second pass through the data. Entries are serialized into MessagePack arrays, using the implementation added in Id2833c5a9. The first element of each array is an entry type specifier. Currently two types exist: TYPE_SINGLE (single sample; no statistical moments) and TYPE_RUNNING (aggregated entry with statistical moments). Additional entry formats may be specified in the future. TYPE_SINGLE entries have the format: [ TYPE_SINGLE, name (string), CPU time (float), wall time (float ] TYPE_RUNNING entries have the format: [ TYPE_RUNNING, name (string), count (int), CPU m1 (float), CPU m2 (float), CPU min (float), CPU max (float), wall m1 (float), wall m2 (float), wall min (float), wall max (float) ] To help reviewers test this change, I have a trivial Python script that can serve as the back-end: Change-Id: I688e7231dad9fcc9d29954afacc47f55d521f58d --- diff --git a/includes/AutoLoader.php b/includes/AutoLoader.php index e6ce693ca1..4905f18572 100644 --- a/includes/AutoLoader.php +++ b/includes/AutoLoader.php @@ -826,6 +826,7 @@ $wgAutoloadLocalClasses = array( # includes/profiler 'Profiler' => 'includes/profiler/Profiler.php', + 'ProfilerMwprof' => 'includes/profiler/ProfilerMwprof.php', 'ProfilerSimple' => 'includes/profiler/ProfilerSimple.php', 'ProfilerSimpleText' => 'includes/profiler/ProfilerSimpleText.php', 'ProfilerSimpleTrace' => 'includes/profiler/ProfilerSimpleTrace.php', diff --git a/includes/profiler/ProfilerMwprof.php b/includes/profiler/ProfilerMwprof.php new file mode 100644 index 0000000000..e81c6ecc8c --- /dev/null +++ b/includes/profiler/ProfilerMwprof.php @@ -0,0 +1,190 @@ +mWorkStack[] = array( $inName, count( $this->mWorkStack ), + $this->getTime(), $this->getTime( 'cpu' ) ); + } + + /** + * Produce an empty function report. + * + * ProfileMwprof does not provide a function report. + * + * @return string Empty string. + */ + public function getFunctionReport() { + return ''; + } + + /** + * Close a profiling section. + * + * Marks the end of the function or code-block that should be timed and + * logged under some specific name. + * + * @param string $outName Section to close + */ + public function profileOut( $outName ) { + list( $inName, $inCount, $inWall, $inCpu ) = array_pop( $this->mWorkStack ); + + // Check for unbalanced profileIn / profileOut calls. + // Bad entries are logged but not sent. + if ( $inName !== $outName ) { + wfDebugLog( 'ProfilerUnbalanced', json_encode( array( $inName, $outName ) ) ); + return; + } + + $elapsedCpu = $this->getTime( 'cpu' ) - $inCpu; + $elapsedWall = $this->getTime() - $inWall; + $this->updateEntry( $outName, $elapsedCpu, $elapsedWall ); + $this->updateTrxProfiling( $outName, $elapsedWall ); + } + + /** + * Update an entry with timing data. + * + * @param string $name Section name + * @param float $elapsedCpu elapsed CPU time + * @param float $elapsedWall elapsed wall-clock time + */ + public function updateEntry( $name, $elapsedCpu, $elapsedWall ) { + // If this is the first measurement for this entry, store plain values. + // Many profiled functions will only be called once per request. + if ( !isset( $this->mCollated[$name] ) ) { + $this->mCollated[$name] = array( + 'cpu' => $elapsedCpu, + 'wall' => $elapsedWall, + 'count' => 1, + ); + return; + } + + $entry = &$this->mCollated[$name]; + + // If it's the second measurement, convert the plain values to + // RunningStat instances, so we can push the incoming values on top. + if ( $entry['count'] === 1 ) { + $cpu = new RunningStat(); + $cpu->push( $entry['cpu'] ); + $entry['cpu'] = $cpu; + + $wall = new RunningStat(); + $wall->push( $entry['wall'] ); + $entry['wall'] = $wall; + } + + $entry['count']++; + $entry['cpu']->push( $elapsedCpu ); + $entry['wall']->push( $elapsedWall ); + } + + /** + * Serialize profiling data and send to a profiling data aggregator. + * + * Individual entries are represented as arrays and then encoded using + * MessagePack, an efficient binary data-interchange format. Encoded + * entries are accumulated into a buffer and sent in batch via UDP to the + * profiling data aggregator. + */ + public function logData() { + global $wgUDPProfilerHost, $wgUDPProfilerPort; + + $this->close(); + + $sock = socket_create( AF_INET, SOCK_DGRAM, SOL_UDP ); + socket_connect( $sock, $wgUDPProfilerHost, $wgUDPProfilerPort ); + $bufferLength = 0; + $buffer = ''; + foreach ( $this->mCollated as $name => $entry ) { + $count = $entry['count']; + $cpu = $entry['cpu']; + $wall = $entry['wall']; + + if ( $count === 1 ) { + $data = array( self::TYPE_SINGLE, $name, $cpu, $wall ); + } else { + $data = array( self::TYPE_RUNNING, $name, $count, + $cpu->m1, $cpu->m2, $cpu->min, $cpu->max, + $wall->m1, $wall->m2, $wall->min, $wall->max ); + } + + $encoded = MWMessagePack::pack( $data ); + $length = strlen( $encoded ); + + // If adding this entry would cause the size of the buffer to + // exceed the standard ethernet MTU size less the UDP header, + // send all pending data and reset the buffer. Otherwise, continue + // accumulating entries into the current buffer. + if ( $length + $bufferLength > 1450 ) { + socket_send( $sock, $buffer, $bufferLength, 0 ); + $buffer = ''; + $bufferLength = 0; + } + $buffer .= $encoded; + $bufferLength += $length; + } + if ( $bufferLength !== 0 ) { + socket_send( $sock, $buffer, $bufferLength, 0 ); + } + } +}