[BUGFIX] Show correct rendering times in admin panel
[Packages/TYPO3.CMS.git] / typo3 / sysext / core / Classes / TimeTracker / TimeTracker.php
1 <?php
2 namespace TYPO3\CMS\Core\TimeTracker;
3
4 /*
5 * This file is part of the TYPO3 CMS project.
6 *
7 * It is free software; you can redistribute it and/or modify it under
8 * the terms of the GNU General Public License, either version 2
9 * of the License, or any later version.
10 *
11 * For the full copyright and license information, please read the
12 * LICENSE.txt file that was distributed with this source code.
13 *
14 * The TYPO3 project - inspiring people to share!
15 */
16 use TYPO3\CMS\Core\Imaging\Icon;
17 use TYPO3\CMS\Core\Imaging\IconFactory;
18 use TYPO3\CMS\Core\SingletonInterface;
19 use TYPO3\CMS\Core\Utility\GeneralUtility;
20
21 /**
22 * Frontend Timetracking functions
23 *
24 * Is used to register how much time is used with operations in TypoScript
25 */
26 class TimeTracker implements SingletonInterface
27 {
28 /**
29 * If set to true (see constructor) then then the timetracking is enabled
30 * @var bool
31 */
32 protected $isEnabled = false;
33
34 /**
35 * Is loaded with the millisecond time when this object is created
36 *
37 * @var int
38 */
39 public $starttime = 0;
40
41 /**
42 * Log Rendering flag. If set, ->push() and ->pull() is called from the cObj->cObjGetSingle().
43 * This determines whether or not the TypoScript parsing activity is logged. But it also slows down the rendering
44 *
45 * @var bool
46 */
47 public $LR = 1;
48
49 /**
50 * @var array
51 */
52 public $printConf = [
53 'showParentKeys' => 1,
54 'contentLength' => 10000,
55 // Determines max length of displayed content before it gets cropped.
56 'contentLength_FILE' => 400,
57 // Determines max length of displayed content FROM FILE cObjects before it gets cropped. Reason is that most FILE cObjects are huge and often used as template-code.
58 'flag_tree' => 1,
59 'flag_messages' => 1,
60 'flag_content' => 0,
61 'allTime' => 0,
62 'keyLgd' => 40
63 ];
64
65 /**
66 * @var array
67 */
68 public $wrapError = [
69 0 => ['', ''],
70 1 => ['<strong>', '</strong>'],
71 2 => ['<strong style="color:#ff6600;">', '</strong>'],
72 3 => ['<strong style="color:#ff0000;">', '</strong>']
73 ];
74
75 /**
76 * @var array
77 */
78 public $wrapIcon = [
79 0 => '',
80 1 => 'actions-document-info',
81 2 => 'status-dialog-warning',
82 3 => 'status-dialog-error'
83 ];
84
85 /**
86 * @var int
87 */
88 public $uniqueCounter = 0;
89
90 /**
91 * @var array
92 */
93 public $tsStack = [[]];
94
95 /**
96 * @var int
97 */
98 public $tsStackLevel = 0;
99
100 /**
101 * @var array
102 */
103 public $tsStackLevelMax = [];
104
105 /**
106 * @var array
107 */
108 public $tsStackLog = [];
109
110 /**
111 * @var int
112 */
113 public $tsStackPointer = 0;
114
115 /**
116 * @var array
117 */
118 public $currentHashPointer = [];
119
120 /**
121 * Log entries that take than this number of milliseconds (own time) will be highlighted during log display. Set 0 to disable highlighting.
122 *
123 * @var int
124 */
125 public $highlightLongerThan = 0;
126
127 /*******************************************
128 *
129 * Logging parsing times in the scripts
130 *
131 *******************************************/
132
133 /**
134 * TimeTracker constructor.
135 *
136 * @param bool $isEnabled
137 */
138 public function __construct($isEnabled = true)
139 {
140 $this->isEnabled = $isEnabled;
141 }
142
143 /**
144 * Sets the starting time
145 */
146 public function start()
147 {
148 if (!$this->isEnabled) {
149 return;
150 }
151 $this->starttime = $this->getMilliseconds();
152 }
153
154 /**
155 * Pushes an element to the TypoScript tracking array
156 *
157 * @param string $tslabel Label string for the entry, eg. TypoScript property name
158 * @param string $value Additional value(?)
159 * @see \TYPO3\CMS\Frontend\ContentObject\ContentObjectRenderer::cObjGetSingle(), pull()
160 */
161 public function push($tslabel, $value = '')
162 {
163 if (!$this->isEnabled) {
164 return;
165 }
166 $this->tsStack[$this->tsStackPointer][] = $tslabel;
167 $this->currentHashPointer[] = 'timetracker_' . $this->uniqueCounter++;
168 $this->tsStackLevel++;
169 $this->tsStackLevelMax[] = $this->tsStackLevel;
170 // setTSlog
171 $k = end($this->currentHashPointer);
172 $this->tsStackLog[$k] = [
173 'level' => $this->tsStackLevel,
174 'tsStack' => $this->tsStack,
175 'value' => $value,
176 'starttime' => microtime(true),
177 'stackPointer' => $this->tsStackPointer
178 ];
179 }
180
181 /**
182 * Pulls an element from the TypoScript tracking array
183 *
184 * @param string $content The content string generated within the push/pull part.
185 * @see \TYPO3\CMS\Frontend\ContentObject\ContentObjectRenderer::cObjGetSingle(), push()
186 */
187 public function pull($content = '')
188 {
189 if (!$this->isEnabled) {
190 return;
191 }
192 $k = end($this->currentHashPointer);
193 $this->tsStackLog[$k]['endtime'] = microtime(true);
194 $this->tsStackLog[$k]['content'] = $content;
195 $this->tsStackLevel--;
196 array_pop($this->tsStack[$this->tsStackPointer]);
197 array_pop($this->currentHashPointer);
198 }
199
200 /**
201 * Logs the TypoScript entry
202 *
203 * @param string $content The message string
204 * @param int $num Message type: 0: information, 1: message, 2: warning, 3: error
205 * @see \TYPO3\CMS\Frontend\ContentObject\ContentObjectRenderer::CONTENT()
206 */
207 public function setTSlogMessage($content, $num = 0)
208 {
209 if (!$this->isEnabled) {
210 return;
211 }
212 end($this->currentHashPointer);
213 $k = current($this->currentHashPointer);
214 $placeholder = '';
215 // Enlarge the "details" column by adding a span
216 if (strlen($content) > 30) {
217 $placeholder = '<br /><span style="width: 300px; height: 1px; display: inline-block;"></span>';
218 }
219 $iconFactory = GeneralUtility::makeInstance(IconFactory::class);
220 $this->tsStackLog[$k]['message'][] = $iconFactory->getIcon($this->wrapIcon[$num], Icon::SIZE_SMALL)->render() . $this->wrapError[$num][0] . htmlspecialchars($content) . $this->wrapError[$num][1] . $placeholder;
221 }
222
223 /**
224 * Set TSselectQuery - for messages in TypoScript debugger.
225 *
226 * @param array $data Query array
227 * @param string $msg Message/Label to attach
228 */
229 public function setTSselectQuery(array $data, $msg = '')
230 {
231 if (!$this->isEnabled) {
232 return;
233 }
234 end($this->currentHashPointer);
235 $k = current($this->currentHashPointer);
236 if ($msg !== '') {
237 $data['msg'] = $msg;
238 }
239 $this->tsStackLog[$k]['selectQuery'][] = $data;
240 }
241
242 /**
243 * Increases the stack pointer
244 *
245 * @see decStackPointer(), \TYPO3\CMS\Frontend\Page\PageGenerator::renderContent(), \TYPO3\CMS\Frontend\ContentObject\ContentObjectRenderer::cObjGetSingle()
246 */
247 public function incStackPointer()
248 {
249 if (!$this->isEnabled) {
250 return;
251 }
252 $this->tsStackPointer++;
253 $this->tsStack[$this->tsStackPointer] = [];
254 }
255
256 /**
257 * Decreases the stack pointer
258 *
259 * @see incStackPointer(), \TYPO3\CMS\Frontend\Page\PageGenerator::renderContent(), \TYPO3\CMS\Frontend\ContentObject\ContentObjectRenderer::cObjGetSingle()
260 */
261 public function decStackPointer()
262 {
263 if (!$this->isEnabled) {
264 return;
265 }
266 unset($this->tsStack[$this->tsStackPointer]);
267 $this->tsStackPointer--;
268 }
269
270 /**
271 * Gets a microtime value as milliseconds value.
272 *
273 * @param float $microtime The microtime value - if not set the current time is used
274 * @return int The microtime value as milliseconds value
275 */
276 public function getMilliseconds($microtime = null)
277 {
278 if (!$this->isEnabled) {
279 return 0;
280 }
281 if (!isset($microtime)) {
282 $microtime = microtime(true);
283 }
284 return round($microtime * 1000);
285 }
286
287 /**
288 * Gets the difference between a given microtime value and the starting time as milliseconds.
289 *
290 * @param float $microtime The microtime value - if not set the current time is used
291 * @return int The difference between a given microtime value and starting time as milliseconds
292 */
293 public function getDifferenceToStarttime($microtime = null)
294 {
295 return $this->getMilliseconds($microtime) - $this->starttime;
296 }
297
298 /**
299 * Get total parse time in milliseconds(without backend user initialization)
300 *
301 * @return int
302 */
303 public function getParseTime(): int
304 {
305 // Compensates for the time consumed with Back end user initialization.
306 $processStart = $this->getMilliseconds($GLOBALS['TYPO3_MISC']['microtime_start'] ?? null);
307
308 $beUserInitializationStart = $this->getMilliseconds($GLOBALS['TYPO3_MISC']['microtime_BE_USER_start'] ?? null);
309 $beUserInitializationEnd = $this->getMilliseconds($GLOBALS['TYPO3_MISC']['microtime_BE_USER_end'] ?? null);
310 $beUserInitialization = $beUserInitializationEnd - $beUserInitializationStart;
311
312 $processEnd = $this->getMilliseconds($GLOBALS['TYPO3_MISC']['microtime_end'] ?? null);
313 $totalParseTime = $processEnd - $processStart;
314
315 if ($beUserInitialization > 0) {
316 $totalParseTime -= $beUserInitialization;
317 }
318
319 return $totalParseTime;
320 }
321
322 /*******************************************
323 *
324 * Printing the parsing time information (for Admin Panel)
325 *
326 *******************************************/
327 /**
328 * Print TypoScript parsing log
329 *
330 * @return string HTML table with the information about parsing times.
331 */
332 public function printTSlog()
333 {
334 if (!$this->isEnabled) {
335 return '';
336 }
337 // Calculate times and keys for the tsStackLog
338 foreach ($this->tsStackLog as $uniqueId => &$data) {
339 $data['endtime'] = $this->getDifferenceToStarttime($data['endtime']);
340 $data['starttime'] = $this->getDifferenceToStarttime($data['starttime']);
341 $data['deltatime'] = $data['endtime'] - $data['starttime'];
342 if (is_array($data['tsStack'])) {
343 $data['key'] = implode($data['stackPointer'] ? '.' : '/', end($data['tsStack']));
344 }
345 }
346 unset($data);
347 // Create hierarchical array of keys pointing to the stack
348 $arr = [];
349 foreach ($this->tsStackLog as $uniqueId => $data) {
350 $this->createHierarchyArray($arr, $data['level'], $uniqueId);
351 }
352 // Parsing the registeret content and create icon-html for the tree
353 $this->tsStackLog[$arr['0.'][0]]['content'] = $this->fixContent($arr['0.'], $this->tsStackLog[$arr['0.'][0]]['content'], '', 0, $arr['0.'][0]);
354 // Displaying the tree:
355 $outputArr = [];
356 $outputArr[] = $this->fw('TypoScript Key');
357 $outputArr[] = $this->fw('Value');
358 if ($this->printConf['allTime']) {
359 $outputArr[] = $this->fw('Time');
360 $outputArr[] = $this->fw('Own');
361 $outputArr[] = $this->fw('Sub');
362 $outputArr[] = $this->fw('Total');
363 } else {
364 $outputArr[] = $this->fw('Own');
365 }
366 $outputArr[] = $this->fw('Details');
367 $out = '';
368 foreach ($outputArr as $row) {
369 $out .= '<th>' . $row . '</th>';
370 }
371 $out = '<thead><tr>' . $out . '</tr></thead>';
372 $flag_tree = $this->printConf['flag_tree'];
373 $flag_messages = $this->printConf['flag_messages'];
374 $flag_content = $this->printConf['flag_content'];
375 $keyLgd = $this->printConf['keyLgd'];
376 $c = 0;
377 foreach ($this->tsStackLog as $uniqueId => $data) {
378 $logRowClass = '';
379 if ($this->highlightLongerThan && (int)$data['owntime'] > (int)$this->highlightLongerThan) {
380 $logRowClass = 'typo3-adminPanel-logRow-highlight';
381 }
382 $item = '';
383 // If first...
384 if (!$c) {
385 $data['icons'] = '';
386 $data['key'] = 'Script Start';
387 $data['value'] = '';
388 }
389 // Key label:
390 $keyLabel = '';
391 if (!$flag_tree && $data['stackPointer']) {
392 $temp = [];
393 foreach ($data['tsStack'] as $k => $v) {
394 $temp[] = GeneralUtility::fixed_lgd_cs(implode($v, $k ? '.' : '/'), -$keyLgd);
395 }
396 array_pop($temp);
397 $temp = array_reverse($temp);
398 array_pop($temp);
399 if (!empty($temp)) {
400 $keyLabel = '<br /><span style="color:#999999;">' . implode($temp, '<br />') . '</span>';
401 }
402 }
403 if ($flag_tree) {
404 $tmp = GeneralUtility::trimExplode('.', $data['key'], true);
405 $theLabel = end($tmp);
406 } else {
407 $theLabel = $data['key'];
408 }
409 $theLabel = GeneralUtility::fixed_lgd_cs($theLabel, -$keyLgd);
410 $theLabel = $data['stackPointer'] ? '<span class="stackPointer">' . $theLabel . '</span>' : $theLabel;
411 $keyLabel = $theLabel . $keyLabel;
412 $item .= '<th scope="row" class="typo3-adminPanel-table-cell-key ' . $logRowClass . '">' . ($flag_tree ? $data['icons'] : '') . $this->fw($keyLabel) . '</th>';
413 // Key value:
414 $keyValue = $data['value'];
415 $item .= '<td class="' . $logRowClass . ' typo3-adminPanel-tsLogTime">' . $this->fw(htmlspecialchars($keyValue)) . '</td>';
416 if ($this->printConf['allTime']) {
417 $item .= '<td class="' . $logRowClass . ' typo3-adminPanel-tsLogTime"> ' . $this->fw($data['starttime']) . '</td>';
418 $item .= '<td class="' . $logRowClass . ' typo3-adminPanel-tsLogTime"> ' . $this->fw($data['owntime']) . '</td>';
419 $item .= '<td class="' . $logRowClass . ' typo3-adminPanel-tsLogTime"> ' . $this->fw(($data['subtime'] ? '+' . $data['subtime'] : '')) . '</td>';
420 $item .= '<td class="' . $logRowClass . ' typo3-adminPanel-tsLogTime"> ' . $this->fw(($data['subtime'] ? '=' . $data['deltatime'] : '')) . '</td>';
421 } else {
422 $item .= '<td class="' . $logRowClass . ' typo3-adminPanel-tsLogTime"> ' . $this->fw($data['owntime']) . '</td>';
423 }
424 // Messages:
425 $msgArr = [];
426 $msg = '';
427 if ($flag_messages && is_array($data['message'])) {
428 foreach ($data['message'] as $v) {
429 $msgArr[] = nl2br($v);
430 }
431 }
432 if ($flag_content && (string)$data['content'] !== '') {
433 $maxlen = 120;
434 // Break lines which are too longer than $maxlen chars (can happen if content contains long paths...)
435 if (preg_match_all('/(\\S{' . $maxlen . ',})/', $data['content'], $reg)) {
436 foreach ($reg[1] as $key => $match) {
437 $match = preg_replace('/(.{' . $maxlen . '})/', '$1 ', $match);
438 $data['content'] = str_replace($reg[0][$key], $match, $data['content']);
439 }
440 }
441 $msgArr[] = nl2br($data['content']);
442 }
443 if (!empty($msgArr)) {
444 $msg = implode($msgArr, '<hr />');
445 }
446 $item .= '<td class="typo3-adminPanel-table-cell-content">' . $this->fw($msg) . '</td>';
447 $out .= '<tr>' . $item . '</tr>';
448 $c++;
449 }
450 $out = '<div class="typo3-adminPanel-table-overflow"><table class="typo3-adminPanel-table typo3-adminPanel-table-debug">' . $out . '</table></div>';
451 return $out;
452 }
453
454 /**
455 * Recursively generates the content to display
456 *
457 * @param array $arr Array which is modified with content. Reference
458 * @param string $content Current content string for the level
459 * @param string $depthData Prefixed icons for new PM icons
460 * @param bool $first Set this for the first call from outside.
461 * @param string $vKey Seems to be the previous tsStackLog key
462 * @return string Returns the $content string generated/modified. Also the $arr array is modified!
463 */
464 protected function fixContent(&$arr, $content, $depthData = '', $first = 0, $vKey = '')
465 {
466 $ac = 0;
467 $c = 0;
468 // First, find number of entries
469 foreach ($arr as $k => $v) {
470 if (\TYPO3\CMS\Core\Utility\MathUtility::canBeInterpretedAsInteger($k)) {
471 $ac++;
472 }
473 }
474 // Traverse through entries
475 $subtime = 0;
476 foreach ($arr as $k => $v) {
477 if (\TYPO3\CMS\Core\Utility\MathUtility::canBeInterpretedAsInteger($k)) {
478 $c++;
479 $deeper = isset($arr[$k . '.']);
480 $LN = $ac == $c ? 'blank' : 'line';
481
482 $BTM = $ac == $c ? 'bottom' : '';
483 $PM = $deeper ? '<i class="fa fa-' . ($deeper ? 'minus' : 'plus') . '-square-o"></i>' : '<span class="treeline-icon treeline-icon-join' . ($BTM ? 'bottom' : '') . '"></span>';
484
485 $this->tsStackLog[$v]['icons'] = $depthData . ($first ? '' : $PM);
486 if ($this->tsStackLog[$v]['content'] !== '') {
487 $content = str_replace($this->tsStackLog[$v]['content'], $v, $content);
488 }
489 if ($deeper) {
490 $this->tsStackLog[$v]['content'] = $this->fixContent($arr[$k . '.'], $this->tsStackLog[$v]['content'], $depthData . ($first ? '' : '<span class="treeline-icon treeline-icon-' . $LN . '"></span>'), 0, $v);
491 } else {
492 $this->tsStackLog[$v]['content'] = $this->fixCLen($this->tsStackLog[$v]['content'], $this->tsStackLog[$v]['value']);
493 $this->tsStackLog[$v]['subtime'] = '';
494 $this->tsStackLog[$v]['owntime'] = $this->tsStackLog[$v]['deltatime'];
495 }
496 $subtime += $this->tsStackLog[$v]['deltatime'];
497 }
498 }
499 // Set content with special chars
500 if (isset($this->tsStackLog[$vKey])) {
501 $this->tsStackLog[$vKey]['subtime'] = $subtime;
502 $this->tsStackLog[$vKey]['owntime'] = $this->tsStackLog[$vKey]['deltatime'] - $subtime;
503 }
504 $content = $this->fixCLen($content, $this->tsStackLog[$vKey]['value']);
505 // Traverse array again, this time substitute the unique hash with the red key
506 foreach ($arr as $k => $v) {
507 if (\TYPO3\CMS\Core\Utility\MathUtility::canBeInterpretedAsInteger($k)) {
508 if ($this->tsStackLog[$v]['content'] !== '') {
509 $content = str_replace($v, '<strong style="color:red;">[' . $this->tsStackLog[$v]['key'] . ']</strong>', $content);
510 }
511 }
512 }
513 // Return the content
514 return $content;
515 }
516
517 /**
518 * Wraps the input content string in green colored span-tags IF the length o fthe input string exceeds $this->printConf['contentLength'] (or $this->printConf['contentLength_FILE'] if $v == "FILE"
519 *
520 * @param string $c The content string
521 * @param string $v Command: If "FILE" then $this->printConf['contentLength_FILE'] is used for content length comparison, otherwise $this->printConf['contentLength']
522 * @return string
523 */
524 protected function fixCLen($c, $v)
525 {
526 $len = $v === 'FILE' ? $this->printConf['contentLength_FILE'] : $this->printConf['contentLength'];
527 if (strlen($c) > $len) {
528 $c = '<span style="color:green;">' . htmlspecialchars(GeneralUtility::fixed_lgd_cs($c, $len)) . '</span>';
529 } else {
530 $c = htmlspecialchars($c);
531 }
532 return $c;
533 }
534
535 /**
536 * Wraps input string in a <span> tag
537 *
538 * @param string $str The string to be wrapped
539 * @return string
540 */
541 protected function fw($str)
542 {
543 return '<span>' . $str . '</span>';
544 }
545
546 /**
547 * Helper function for internal data manipulation
548 *
549 * @param array $arr Array (passed by reference) and modified
550 * @param int $pointer Pointer value
551 * @param string $uniqueId Unique ID string
552 * @access private
553 * @see printTSlog()
554 */
555 protected function createHierarchyArray(&$arr, $pointer, $uniqueId)
556 {
557 if (!is_array($arr)) {
558 $arr = [];
559 }
560 if ($pointer > 0) {
561 end($arr);
562 $k = key($arr);
563 $this->createHierarchyArray($arr[(int)$k . '.'], $pointer - 1, $uniqueId);
564 } else {
565 $arr[] = $uniqueId;
566 }
567 }
568 }