Code Coverage |
||||||||||
Lines |
Functions and Methods |
Classes and Traits |
||||||||
| Total | |
0.00% |
0 / 87 |
|
0.00% |
0 / 15 |
CRAP | |
0.00% |
0 / 1 |
| Profile | |
0.00% |
0 / 87 |
|
0.00% |
0 / 15 |
756 | |
0.00% |
0 / 1 |
| start | |
0.00% |
0 / 1 |
|
0.00% |
0 / 1 |
2 | |||
| end | |
0.00% |
0 / 1 |
|
0.00% |
0 / 1 |
2 | |||
| pushNestedProfile | |
0.00% |
0 / 1 |
|
0.00% |
0 / 1 |
2 | |||
| bumpProfileTimeUse | |
0.00% |
0 / 9 |
|
0.00% |
0 / 1 |
20 | |||
| bumpTimeUse | |
0.00% |
0 / 1 |
|
0.00% |
0 / 1 |
2 | |||
| bumpMWTime | |
0.00% |
0 / 1 |
|
0.00% |
0 / 1 |
2 | |||
| bumpCount | |
0.00% |
0 / 2 |
|
0.00% |
0 / 1 |
2 | |||
| formatLine | |
0.00% |
0 / 5 |
|
0.00% |
0 / 1 |
12 | |||
| cmpProfile | |
0.00% |
0 / 1 |
|
0.00% |
0 / 1 |
2 | |||
| formatProfile | |
0.00% |
0 / 25 |
|
0.00% |
0 / 1 |
30 | |||
| printProfile | |
0.00% |
0 / 25 |
|
0.00% |
0 / 1 |
6 | |||
| swallowArray | |
0.00% |
0 / 3 |
|
0.00% |
0 / 1 |
6 | |||
| reduce | |
0.00% |
0 / 6 |
|
0.00% |
0 / 1 |
6 | |||
| reduceProfileTree | |
0.00% |
0 / 5 |
|
0.00% |
0 / 1 |
2 | |||
| |
0.00% |
0 / 1 |
|
0.00% |
0 / 1 |
2 | ||||
| 1 | <?php |
| 2 | declare( strict_types = 1 ); |
| 3 | |
| 4 | namespace Wikimedia\Parsoid\Config; |
| 5 | |
| 6 | /** |
| 7 | * Records time profiling information |
| 8 | */ |
| 9 | class Profile { |
| 10 | /** @var int|float - int on 64-bit systems */ |
| 11 | public $startTime; |
| 12 | |
| 13 | /** @var int|float - int on 64-bit systems */ |
| 14 | public $endTime; |
| 15 | |
| 16 | private array $timeProfile = []; |
| 17 | private array $mwProfile = []; |
| 18 | private array $timeCategories = []; |
| 19 | private array $counts = []; |
| 20 | |
| 21 | /** |
| 22 | * Array of profiles for nested pipelines. So, we effectively end up with |
| 23 | * a profile tree with the top-level-doc profile as the root profile. |
| 24 | * @var array<Profile> |
| 25 | */ |
| 26 | private array $nestedProfiles = []; |
| 27 | |
| 28 | /** |
| 29 | * This is the most recently pushed nested profile from a nested pipeline. |
| 30 | * @var ?Profile |
| 31 | */ |
| 32 | private ?Profile $recentNestedProfile = null; |
| 33 | |
| 34 | public function start(): void { |
| 35 | $this->startTime = hrtime( true ); |
| 36 | } |
| 37 | |
| 38 | public function end(): void { |
| 39 | $this->endTime = hrtime( true ); |
| 40 | } |
| 41 | |
| 42 | public function pushNestedProfile( Profile $p ): void { |
| 43 | $this->nestedProfiles[] = $this->recentNestedProfile = $p; |
| 44 | } |
| 45 | |
| 46 | /** |
| 47 | * @param array &$profile |
| 48 | * @param string $resource |
| 49 | * @param int|float $time Time in nanoseconds |
| 50 | * @param ?string $cat |
| 51 | */ |
| 52 | private function bumpProfileTimeUse( |
| 53 | array &$profile, string $resource, $time, ?string $cat |
| 54 | ): void { |
| 55 | $time /= 1000000; // ns --> ms |
| 56 | if ( $profile === $this->timeProfile && $this->recentNestedProfile ) { |
| 57 | // Eliminate double-counting |
| 58 | $time -= ( $this->recentNestedProfile->endTime - $this->recentNestedProfile->startTime ) / 1000000; |
| 59 | $this->recentNestedProfile = null; |
| 60 | } |
| 61 | |
| 62 | $profile[$resource] ??= 0; |
| 63 | $profile[$resource] += $time; |
| 64 | if ( $cat ) { |
| 65 | $this->timeCategories[$cat] ??= 0; |
| 66 | $this->timeCategories[$cat] += $time; |
| 67 | } |
| 68 | } |
| 69 | |
| 70 | /** |
| 71 | * Update a profile timer. |
| 72 | * |
| 73 | * @param string $resource |
| 74 | * @param int|float $time Time in nanoseconds |
| 75 | * @param string|null $cat |
| 76 | */ |
| 77 | public function bumpTimeUse( string $resource, $time, ?string $cat = null ): void { |
| 78 | $this->bumpProfileTimeUse( $this->timeProfile, $resource, $time, $cat ); |
| 79 | } |
| 80 | |
| 81 | /** |
| 82 | * Update profile usage for "MW API" requests |
| 83 | * |
| 84 | * @param string $resource |
| 85 | * @param int|float $time Time in nanoseconds |
| 86 | * @param string|null $cat |
| 87 | */ |
| 88 | public function bumpMWTime( string $resource, $time, ?string $cat = null ): void { |
| 89 | // FIXME: For now, skip the category since this leads to double counting |
| 90 | // when reportind time by categories since this time is part of other |
| 91 | // '$this->timeProfile' categories already. |
| 92 | $this->bumpProfileTimeUse( $this->mwProfile, $resource, $time, null ); |
| 93 | } |
| 94 | |
| 95 | /** |
| 96 | * Update a profile counter. |
| 97 | * |
| 98 | * @param string $resource |
| 99 | * @param int $n The amount to increment the counter; defaults to 1. |
| 100 | */ |
| 101 | public function bumpCount( string $resource, int $n = 1 ): void { |
| 102 | $this->counts[$resource] ??= 0; |
| 103 | $this->counts[$resource] += $n; |
| 104 | } |
| 105 | |
| 106 | /** |
| 107 | * @param string $k |
| 108 | * @param mixed $v |
| 109 | * @param string $comment |
| 110 | * @return string |
| 111 | */ |
| 112 | private function formatLine( string $k, $v, string $comment = '' ): string { |
| 113 | $buf = str_pad( $k, 60, " ", STR_PAD_LEFT ) . ':'; |
| 114 | if ( $v === round( $v ) ) { |
| 115 | $v = (string)$v; |
| 116 | } else { |
| 117 | $v = str_pad( (string)( floor( $v * 10000 ) / 10000 ), 5, ' ', STR_PAD_LEFT ); |
| 118 | } |
| 119 | return $buf . str_pad( $v, 10, " ", STR_PAD_LEFT ) . ( $comment ? ' (' . $comment . ')' : '' ); |
| 120 | } |
| 121 | |
| 122 | /** |
| 123 | * Sort comparison function |
| 124 | * @param array $a |
| 125 | * @param array $b |
| 126 | * @return float |
| 127 | */ |
| 128 | private static function cmpProfile( array $a, array $b ): float { |
| 129 | return $b[1] - $a[1]; |
| 130 | } |
| 131 | |
| 132 | private function formatProfile( array $profile, array $options = [] ): array { |
| 133 | // Sort time profile in descending order |
| 134 | |
| 135 | $total = 0; |
| 136 | $outLines = []; |
| 137 | foreach ( $profile as $k => $v ) { |
| 138 | $total += $v; |
| 139 | $outLines[] = [ $k, $v ]; |
| 140 | } |
| 141 | |
| 142 | usort( $outLines, [ self::class, 'cmpProfile' ] ); |
| 143 | |
| 144 | $lines = []; |
| 145 | foreach ( $outLines as $line ) { |
| 146 | $k = $line[0]; |
| 147 | $v = $line[1]; |
| 148 | $lineComment = ''; |
| 149 | if ( isset( $options['printPercentage'] ) ) { |
| 150 | $lineComment = (string)( round( $v * 1000 / $total ) / 10 ) . '%'; |
| 151 | } |
| 152 | |
| 153 | $buf = $this->formatLine( $k, $v, $lineComment ); |
| 154 | if ( isset( $this->counts[$k] ) ) { |
| 155 | $buf .= str_pad( '; count: ' . |
| 156 | str_pad( (string)( $this->counts[$k] ), 6, ' ', STR_PAD_LEFT ), |
| 157 | 6, " ", STR_PAD_LEFT ); |
| 158 | $buf .= str_pad( '; per-instance: ' . |
| 159 | str_pad( |
| 160 | (string)( floor( $v * 10000 / $this->counts[$k] ) / 10000 ), 5, ' ', STR_PAD_LEFT |
| 161 | ), 10 ); |
| 162 | } |
| 163 | $lines[] = $buf; |
| 164 | } |
| 165 | return [ 'buf' => implode( "\n", $lines ), 'total' => $total ]; |
| 166 | } |
| 167 | |
| 168 | private function printProfile(): string { |
| 169 | $outLines = []; |
| 170 | $mwOut = $this->formatProfile( $this->mwProfile ); |
| 171 | $cpuOut = $this->formatProfile( $this->timeProfile ); |
| 172 | |
| 173 | $outLines[] = str_repeat( "-", 85 ); |
| 174 | $outLines[] = "Recorded times (in ms) for various parse components"; |
| 175 | $outLines[] = ""; |
| 176 | $outLines[] = $cpuOut['buf']; |
| 177 | $outLines[] = str_repeat( "-", 85 ); |
| 178 | $outLines[] = 'Recorded times (in ms) for various "MW API" requests'; |
| 179 | $outLines[] = ""; |
| 180 | $outLines[] = $mwOut['buf']; |
| 181 | $outLines[] = str_repeat( "-", 85 ); |
| 182 | $parseTime = ( $this->endTime - $this->startTime ) / 1000000; |
| 183 | $outLines[] = $this->formatLine( 'TOTAL PARSE TIME (1)', $parseTime ); |
| 184 | $outLines[] = $this->formatLine( 'TOTAL PARSOID CPU TIME (2)', $cpuOut['total'] ); |
| 185 | if ( $mwOut['total'] > 0 ) { |
| 186 | $outLines[] = $this->formatLine( 'TOTAL "MW API" TIME', $mwOut['total'] ); |
| 187 | } |
| 188 | $outLines[] = $this->formatLine( 'Un/over-accounted parse time: (1) - (2)', |
| 189 | $parseTime - $cpuOut['total'] ); |
| 190 | $outLines[] = ""; |
| 191 | $catOut = $this->formatProfile( $this->timeCategories, [ 'printPercentage' => true ] ); |
| 192 | $outLines[] = $catOut['buf']; |
| 193 | $outLines[] = ""; |
| 194 | $outLines[] = str_repeat( "-", 85 ); |
| 195 | |
| 196 | // dump to stderr via error_log |
| 197 | return implode( "\n", $outLines ); |
| 198 | } |
| 199 | |
| 200 | private static function swallowArray( array $a, array &$res ): void { |
| 201 | foreach ( $a as $k => $v ) { |
| 202 | $res[$k] ??= 0; |
| 203 | $res[$k] += $v; |
| 204 | } |
| 205 | } |
| 206 | |
| 207 | private function reduce( Profile $reducedProfile ): void { |
| 208 | self::swallowArray( $this->counts, $reducedProfile->counts ); |
| 209 | self::swallowArray( $this->timeCategories, $reducedProfile->timeCategories ); |
| 210 | self::swallowArray( $this->timeProfile, $reducedProfile->timeProfile ); |
| 211 | self::swallowArray( $this->mwProfile, $reducedProfile->mwProfile ); |
| 212 | |
| 213 | foreach ( $this->nestedProfiles as $p ) { |
| 214 | $p->reduce( $reducedProfile ); |
| 215 | } |
| 216 | } |
| 217 | |
| 218 | private function reduceProfileTree(): Profile { |
| 219 | $reducedProfile = new Profile(); |
| 220 | $reducedProfile->startTime = $this->startTime; |
| 221 | $reducedProfile->endTime = $this->endTime; |
| 222 | $this->reduce( $reducedProfile ); |
| 223 | return $reducedProfile; |
| 224 | } |
| 225 | |
| 226 | public function print(): string { |
| 227 | return $this->reduceProfileTree()->printProfile(); |
| 228 | } |
| 229 | } |