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