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