ExcimerLog::formatCollapsed() produces an extra semi-colon at the beginning of each line
Closed, ResolvedPublicBUG REPORT
Actions

Assigned To

Authored By

	Jasondendulk
	Nov 26 2021, 11:48 AM

Description

How to reproduce

Use Excimer to profile any PHP execution large enough to produce at least two records.
Use formatCollapsed() to produce a single string profile, and output it to a file.
Examine the file to see the extra semi-colons.

An extra semi-colon is prepended to each line. When submitted to flamegraph, it results in skewed images.

example

/var/www/excimer/admin/search.php;moodle_needs_upgrading;core_component::get_all_versions_hash;core_component::get_all_versions;core_component::fetch_plugins 1
;/var/www/excimer/admin/search.php;admin_externalpage_setup;admin_get_root;/var/www/excimer/admin/settings/plugins.php;admin_category::add;admin_category::locate 1
;/var/www/excimer/admin/search.php;admin_externalpage_setup;moodle_page::__get;moodle_page::magic_get_settingsnav;settings_navigation::initialise;settings_navigation::load_administration_settings;settings_navigation::load_administration_settings;settings_navigation::load_administration_settings;settings_navigation::load_administration_settings;settings_navigation::load_administration_settings;admin_settingpage::check_access;has_capability 1
;/var/www/excimer/admin/search.php;admin_get_root;/var/www/excimer/admin/settings/plugins.php;core\plugininfo\auth::load_settings;/var/www/excimer/auth/cas/settings.php;display_auth_lock_options;admin_setting_configselect::__construct 1
;/var/www/excimer/admin/search.php;admin_get_root;/var/www/excimer/admin/settings/plugins.php;lang_string::__construct;core_string_manager_standard::string_exists;core_string_manager_standard::load_component_strings;core_component::normalize_component 1

There should be no semi-colons at the beginning of each line.

Bug occurs in version: 1.0.2

An examination of the source code shows the problem occurs on line 315 of excimer_log.c.

if (excimer_log_smart_str_get_len(&buf) != 0) {
    smart_str_appends(&buf, ";");
}

Because buf is empty only at the very beginning of the function, it will cause a semi-colon to be appended at the start of each line.

This flaw was also found in the master branch.

Thank you for your consideration.

Regards, Jason

Details

	Subject	Repo	Branch	Lines +/-
	tests: Add regression test for formatCollapsed line formatting	mediawiki/php/excimer	master	+19 -18

Customize query in gerrit

Event Timeline

Jasondendulk created this task.Nov 26 2021, 11:48 AM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptNov 26 2021, 11:48 AM

Krinkle added a project: Performance-Team.Dec 15 2022, 7:12 AM

I'll take a look at repro'ing this to see if it is still an issue. Tim's recent change may've fixed this.

Krinkle moved this task from Inbox, needs triage to Doing: Prio Interrupt on the Performance-Team board.Dec 19 2022, 7:33 PM

Confirmed in Excimer 1.0.4 (php8.1-excimer 1.0.4-1+0~20221216.1+debian10~1.gbp44aab6, via deb.sury.org).

<?php

function main() { foo(); bar(); }
function foo() {
  $i = 10000;
  while ($i--) { usleep(100); $x = str_repeat('x', $i); }
  return $x;
}
function bar() { foo(); }

$profiler = new ExcimerProfiler;
$profiler->setPeriod( 0.001 ); // every 1ms
$profiler->setEventType( EXCIMER_REAL );
$profiler->start();
register_shutdown_function( function () use ( $profiler ) {
  $profiler->stop();
  file_put_contents('trace.log', $profiler->getLog()->formatCollapsed());
} );

main();

trace.log

/var/www/html/w/tmp.php;main;foo 2240
;/var/www/html/w/tmp.php;main;foo 2
;/var/www/html/w/tmp.php;main;bar;foo 2257
;/var/www/html/w/tmp.php;main;bar;foo 1
;{closure:/var/www/html/w/tmp.php(23)} 1

I've also confirmed that both brendangregg/FlameGraph and jlfwong/speedscope interpret that as a leading frame with the empty string as its name.

Krinkle triaged this task as Medium priority.Jan 5 2023, 6:55 PM

Change 875996 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/php/excimer@master] tests: Add regression test for formatCollapsed line formatting

https://gerrit.wikimedia.org/r/875996

gerritbot added a project: Patch-For-Review.Jan 5 2023, 7:28 PM

Change 875996 merged by jenkins-bot:

[mediawiki/php/excimer@master] tests: Add regression test for formatCollapsed line formatting

https://gerrit.wikimedia.org/r/875996

Maintenance_bot removed a project: Patch-For-Review.Jan 5 2023, 11:30 PM

Krinkle closed this task as Resolved.Jan 9 2023, 5:12 PM

ExcimerLog::formatCollapsed() produces an extra semi-colon at the beginning of each lineClosed, ResolvedPublicBUG REPORTActions

Description

Details

Event Timeline

ExcimerLog::formatCollapsed() produces an extra semi-colon at the beginning of each line
Closed, ResolvedPublicBUG REPORT
Actions