Code Coverage
 
Lines
Functions and Methods
Classes and Traits
Total
0.00% covered (danger)
0.00%
0 / 86
0.00% covered (danger)
0.00%
0 / 15
CRAP
0.00% covered (danger)
0.00%
0 / 1
Profile
0.00% covered (danger)
0.00%
0 / 86
0.00% covered (danger)
0.00%
0 / 15
756
0.00% covered (danger)
0.00%
0 / 1
 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 / 8
0.00% covered (danger)
0.00%
0 / 1
20
 bumpTimeUse
0.00% covered (danger)
0.00%
0 / 1
0.00% covered (danger)
0.00%
0 / 1
2
 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 / 25
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 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}