diff --git a/CHANGELOG.md b/CHANGELOG.md index ac069c0989d..2732ccb8a3c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -184,6 +184,7 @@ The present file will list all changes made to the project; according to the - `Toolbox::seems_utf8()` - `Toolbox::stripslashes_deep()` - `Search::getOptions()` no longer returns a reference +- `Timer` class. Use `Glpi\Debug\Profiler` instead. #### Removed - Usage of `csrf_compliant` plugins hook. @@ -255,6 +256,9 @@ The present file will list all changes made to the project; according to the - `Config::showLibrariesInformation()` - `DisplayPreference::showFormGlobal` `target` parameter. - `DisplayPreference::showFormPerso` `target_id` parameter. +- `DEBUG_SQL` and `SQL_TOTAL_REQUEST` globals. Replaced by `Glpi\Debug\Profile` class. +- `debug_sql` and `debug_vars` options for `$CFG_GLPI` configuration array. +- `TIMER_DEBUG` and `TIMER` globals. ## [10.0.12] unreleased diff --git a/inc/define.php b/inc/define.php index 7dc74c8c593..fba7960e2de 100644 --- a/inc/define.php +++ b/inc/define.php @@ -448,10 +448,6 @@ $CFG_GLPI["number_format"] = 0; $CFG_GLPI["decimal_number"] = 2; -// Default debug options : may be locally overriden -$CFG_GLPI["debug_sql"] = $CFG_GLPI["debug_vars"] = $CFG_GLPI["debug_lang"] = 1; - - // User Prefs fields which override $CFG_GLPI config $CFG_GLPI['user_pref_field'] = ['backcreated', 'csv_delimiter', 'date_format', 'default_requesttypes_id', 'display_count_on_home', diff --git a/inc/includes.php b/inc/includes.php index f62d5ab9c7a..82fa211cfa9 100644 --- a/inc/includes.php +++ b/inc/includes.php @@ -48,9 +48,6 @@ include_once GLPI_ROOT . '/inc/based_config.php'; -// Init Timer to compute time of display -$TIMER_DEBUG = new Timer(); -$TIMER_DEBUG->start(); \Glpi\Debug\Profiler::getInstance()->start('php_request'); @@ -77,12 +74,6 @@ ) { // Start the debug profile $profile = \Glpi\Debug\Profile::getCurrent(); - $SQL_TOTAL_REQUEST = 0; - $DEBUG_SQL = [ - 'queries' => [], - 'errors' => [], - 'times' => [], - ]; } // Mark if Header is loaded or not : diff --git a/src/Api/API.php b/src/Api/API.php index fc5c645240e..9e145fa9a01 100644 --- a/src/Api/API.php +++ b/src/Api/API.php @@ -52,6 +52,7 @@ use Dropdown; use Glpi\Api\HL\Router; use Glpi\DBAL\QueryExpression; +use Glpi\Debug\Profile; use Glpi\Search\Provider\SQLProvider; use Glpi\Search\SearchOption; use Glpi\Toolbox\MarkdownRenderer; @@ -1572,9 +1573,6 @@ private function getSearchOptionUniqIDJoins($option) */ protected function searchItems($itemtype, $params = []) { - /** @var array $DEBUG_SQL */ - global $DEBUG_SQL; - $itemtype = $this->handleDepreciation($itemtype); // check rights @@ -1673,16 +1671,13 @@ protected function searchItems($itemtype, $params = []) // force reset $params['reset'] = 'reset'; - // force logging sql queries - $_SESSION['glpi_use_mode'] = Session::DEBUG_MODE; - // call Core Search method $rawdata = Search::getDatas($itemtype, $params, $params['forcedisplay']); // probably a sql error if (!isset($rawdata['data']) || count($rawdata['data']) === 0) { $this->returnError( - "Unexpected SQL Error : " . array_splice($DEBUG_SQL['errors'], -2)[0], + 'An internal error occured while trying to fetch the data.', 500, "ERROR_SQL", false @@ -2352,9 +2347,6 @@ private function unlockSessionIfPossible() */ private function getGlpiLastMessage() { - /** @var array $DEBUG_SQL */ - global $DEBUG_SQL; - $all_messages = []; $messages_after_redirect = []; @@ -2376,11 +2368,8 @@ private function getGlpiLastMessage() } // get sql errors - if ( - count($all_messages) <= 0 - && ($DEBUG_SQL['errors'] ?? null) !== null - ) { - $all_messages = $DEBUG_SQL['errors']; + if (count($all_messages) <= 0) { + $all_messages = Profile::getCurrent()->getSQLErrors(); } if (!end($all_messages)) { diff --git a/src/Console/Application.php b/src/Console/Application.php index 4457ed9df75..bdd8025c3dc 100644 --- a/src/Console/Application.php +++ b/src/Console/Application.php @@ -310,25 +310,12 @@ protected function doRunCommand(Command $command, InputInterface $input, OutputI /** * Initalize GLPI. * - * @global array $CFG_GLPI * @global GLPI $GLPI * * @return void */ private function initApplication() { - - // Disable debug at bootstrap (will be re-enabled later if requested by verbosity level). - /** @var array $CFG_GLPI */ - global $CFG_GLPI; - $CFG_GLPI = array_merge( - $CFG_GLPI, - [ - 'debug_sql' => 0, - 'debug_vars' => 0, - ] - ); - /** @var \GLPI $GLPI */ global $GLPI; $GLPI = new GLPI(); diff --git a/src/DBmysql.php b/src/DBmysql.php index 0a1720b2b3c..4c35a49a7f6 100644 --- a/src/DBmysql.php +++ b/src/DBmysql.php @@ -38,6 +38,7 @@ use Glpi\DBAL\QueryParam; use Glpi\DBAL\QuerySubQuery; use Glpi\DBAL\QueryUnion; +use Glpi\Debug\Profiler; use Glpi\System\Requirement\DbTimezones; /** @@ -359,10 +360,6 @@ public function escape($string) * * @param string $query Query to execute * - * @var array $CFG_GLPI - * @var array $DEBUG_SQL - * @var integer $SQL_TOTAL_REQUEST - * * @return mysqli_result|boolean Query result handler * * @deprecated 10.0.11 @@ -377,23 +374,10 @@ public function query($query) * * @param string $query Query to execute * - * @var array $CFG_GLPI - * @var array $DEBUG_SQL - * @var integer $SQL_TOTAL_REQUEST - * * @return mysqli_result|boolean Query result handler */ public function doQuery($query) { - /** - * @var array $CFG_GLPI - * @var array $DEBUG_SQL - * @var integer $SQL_TOTAL_REQUEST - */ - global $CFG_GLPI, $DEBUG_SQL, $SQL_TOTAL_REQUEST; - - //FIXME Remove use of $DEBUG_SQL and $SQL_TOTAL_REQUEST - $debug_data = [ 'query' => $query, 'time' => 0, @@ -403,13 +387,8 @@ public function doQuery($query) ]; $is_debug = isset($_SESSION['glpi_use_mode']) && ($_SESSION['glpi_use_mode'] == Session::DEBUG_MODE); - if ($is_debug && $CFG_GLPI["debug_sql"]) { - $SQL_TOTAL_REQUEST++; - $DEBUG_SQL["queries"][$SQL_TOTAL_REQUEST] = $query; - } - $TIMER = new Timer(); - $TIMER->start(); + Profiler::getInstance()->start('sql_query', Profiler::CATEGORY_DB, true); $this->checkForDeprecatedTableOptions($query); @@ -424,22 +403,18 @@ public function doQuery($query) ErrorHandler::getInstance()->handleSqlError($this->dbh->errno, $this->dbh->error, $query); - if (($is_debug || isAPI()) && $CFG_GLPI["debug_sql"]) { - $DEBUG_SQL["errors"][$SQL_TOTAL_REQUEST] = $this->error(); + if (($is_debug || isAPI())) { $debug_data['errors'] = $this->error(); } } - if ($is_debug && $CFG_GLPI["debug_sql"]) { - $TIME = $TIMER->getTime(); - $debug_data['time'] = (int) ($TIME * 1000); + $duration = Profiler::getInstance()->stop('sql_query', true); + if ($is_debug) { + $debug_data['time'] = $duration; $debug_data['rows'] = $this->affectedRows(); - $DEBUG_SQL["times"][$SQL_TOTAL_REQUEST] = $TIME; - $DEBUG_SQL['rows'][$SQL_TOTAL_REQUEST] = $this->affectedRows(); } $this->last_query_warnings = $this->fetchQueryWarnings(); - $DEBUG_SQL['warnings'][$SQL_TOTAL_REQUEST] = $this->last_query_warnings; $warnings_string = implode( "\n", @@ -473,7 +448,7 @@ static function ($warning) { $debug_data['warnings'] ); if ($this->execution_time === true) { - $this->execution_time = $TIMER->getTime(0, true); + $this->execution_time = $duration; } return $res; } @@ -535,13 +510,6 @@ public function doQueryOrDie($query, $message = '') */ public function prepare($query) { - /** - * @var array $CFG_GLPI - * @var array $DEBUG_SQL - * @var integer $SQL_TOTAL_REQUEST - */ - global $CFG_GLPI, $DEBUG_SQL, $SQL_TOTAL_REQUEST; - $res = $this->dbh->prepare($query); if (!$res) { // no translation for error logs @@ -553,13 +521,12 @@ public function prepare($query) ErrorHandler::getInstance()->handleSqlError($this->dbh->errno, $this->dbh->error, $query); - if ( - isset($_SESSION['glpi_use_mode']) - && $_SESSION['glpi_use_mode'] == Session::DEBUG_MODE - && $CFG_GLPI["debug_sql"] - ) { - $SQL_TOTAL_REQUEST++; - $DEBUG_SQL["errors"][$SQL_TOTAL_REQUEST] = $this->error(); + if (isset($_SESSION['glpi_use_mode']) && $_SESSION['glpi_use_mode'] == Session::DEBUG_MODE) { + \Glpi\Debug\Profile::getCurrent()->addSQLQueryData( + query: $query, + time: 0, + errors: $this->error() + ); } } $this->current_query = $query; diff --git a/src/Debug/Profile.php b/src/Debug/Profile.php index 08037c7d466..5ca9d977f11 100644 --- a/src/Debug/Profile.php +++ b/src/Debug/Profile.php @@ -55,6 +55,8 @@ final class Profile private static ?self $current = null; + private $disabled = false; + public function __construct(string $id, ?string $parent_id) { $this->id = $id; @@ -78,6 +80,25 @@ public static function getCurrent(): self return self::$current; } + /** + * Stops the collection of new debug data. + * This does not clear any existing data or prevent the existing data from being saved. + * @return void + */ + public function disable(): void + { + $this->disabled = true; + } + + /** + * Re-enables the collection of new debug data. + * @return void + */ + public function enable(): void + { + $this->disabled = false; + } + public static function pull(string $id): ?self { if (!isset($_SESSION['debug_profiles'][$id])) { @@ -110,6 +131,9 @@ public function getParentID(): ?string public function setData(string $widget, $data) { + if ($this->disabled) { + return; + } if (!array_key_exists($widget, $this->additional_info)) { $this->additional_info[$widget] = []; } @@ -118,6 +142,9 @@ public function setData(string $widget, $data) public function addSQLQueryData(string $query, int $time, int $rows = 0, string $errors = '', string $warnings = '') { + if ($this->disabled) { + return; + } if (!array_key_exists('sql', $this->additional_info)) { $this->additional_info['sql'] = [ 'queries' => [], @@ -134,6 +161,17 @@ public function addSQLQueryData(string $query, int $time, int $rows = 0, string ]; } + public function getSQLErrors(): array + { + $errors = []; + foreach ($this->additional_info['sql']['queries'] ?? [] as $query) { + if ($query['errors'] !== '') { + $errors[] = $query; + } + } + return $errors; + } + public function getDebugInfo(): array { if ($this->is_readonly) { @@ -191,6 +229,10 @@ public function getDebugInfo(): array public function save(): void { + if ($_SESSION['glpi_use_mode'] !== \Session::DEBUG_MODE) { + // Don't save debug info for non-debug requests + return; + } if (isAPI() || isCommandLine()) { // No saving debug info for API or CLI requests return; diff --git a/src/Debug/Profiler.php b/src/Debug/Profiler.php index 20537d31aad..35e64286f1a 100644 --- a/src/Debug/Profiler.php +++ b/src/Debug/Profiler.php @@ -71,12 +71,15 @@ public function disable(): void * Starts a new section in the profiler. This section will be stopped when Profiler::stop() is called with the same name. * @param string $name The name of the section. This name will be used to stop the section later. * @param string $category The category of the section. See Profiler::CATEGORY_* for some predefined categories. + * @param bool $force_start If true, the section will be started even if the user is not in debug mode. + * This is useful if the profiler is going to be used to simply time a section of code and + * the result will be used in the application. * @return void */ - public function start(string $name, string $category = self::CATEGORY_CORE): void + public function start(string $name, string $category = self::CATEGORY_CORE, bool $force_start = false): void { $debug_mode_or_pre_session = !isset($_SESSION['glpi_use_mode']) || $_SESSION['glpi_use_mode'] === \Session::DEBUG_MODE; - if ($this->disabled || !$debug_mode_or_pre_session) { + if (!$force_start && ($this->disabled || !$debug_mode_or_pre_session)) { return; } @@ -126,9 +129,10 @@ public function resume(string $name): void /** * Stops a section started with Profiler::start() * @param string $name The name of the section to stop. This name must be the same as the one used in Profiler::start() - * @return void + * @param bool $discard If true, the section will not be added to the debug information. + * @return int The duration of the section in milliseconds */ - public function stop(string $name): void + public function stop(string $name, bool $discard = false): int { // get the last section with the given name and stop it $section = array_filter($this->current_sections, static function (ProfilerSection $section) use ($name) { @@ -138,9 +142,30 @@ public function stop(string $name): void $k = array_key_last($section); $section = array_pop($section); $section->end(microtime(true) * 1000); + $duration = $section->getDuration(); unset($this->current_sections[$k]); - Profile::getCurrent()->setData('profiler', $section->toArray()); + if (!$discard) { + Profile::getCurrent()->setData('profiler', $section->toArray()); + } + } + return $duration ?? 0; + } + + /** + * Get the current duration of a running section by name without stopping it. + * @param string $name The name of the section to get the duration of. + * @return int The duration of the section in milliseconds + */ + public function getCurrentDuration(string $name): int + { + $section = array_filter($this->current_sections, static function (ProfilerSection $section) use ($name) { + return $section->getName() === $name; + }); + if (count($section)) { + $section = array_pop($section); + return $section->getDuration(); } + return 0; } /** diff --git a/src/MassiveAction.php b/src/MassiveAction.php index 9c3f33e7ac6..e6c1bac0971 100644 --- a/src/MassiveAction.php +++ b/src/MassiveAction.php @@ -33,6 +33,7 @@ * --------------------------------------------------------------------- */ +use Glpi\Debug\Profiler; use Glpi\Features\Clonable; use Glpi\Search\SearchOption; @@ -130,12 +131,6 @@ class MassiveAction */ private $timeout_delay; - /** - * Current process timer. - * @var int - */ - private $timer; - /** * Item used to check rights. * Variable is used for caching purpose. @@ -410,9 +405,7 @@ public function __construct(array $POST, array $GET, $stage, ?int $items_id = nu $this->fields_to_remove_when_reload = ['fields_to_remove_when_reload']; - $this->timer = new Timer(); - $this->timer->start(); - $this->fields_to_remove_when_reload[] = 'timer'; + Profiler::getInstance()->start(name: 'MassiveAction:' . $this->identifier, force_start: true); $max_time = (get_cfg_var("max_execution_time") == 0) ? 60 : get_cfg_var("max_execution_time"); @@ -457,7 +450,6 @@ public function __get(string $property) case 'redirect': case 'remainings': case 'timeout_delay': - case 'timer': Toolbox::deprecated(sprintf('Reading private property %s::%s is deprecated', __CLASS__, $property)); $value = $this->$property; break; @@ -495,7 +487,6 @@ public function __set(string $property, $value) case 'redirect': case 'remainings': case 'timeout_delay': - case 'timer': Toolbox::deprecated(sprintf('Writing private property %s::%s is deprecated', __CLASS__, $property)); $this->$property = $value; break; @@ -1337,7 +1328,7 @@ public function updateProgressBars() return; } - if ($this->timer->getTime() > 1) { + if (Profiler::getInstance()->getCurrentDuration('MassiveAction:' . $this->identifier) > 1000) { // If the action's delay is more than one second, the display progress bars $this->display_progress_bars = true; } @@ -1868,7 +1859,7 @@ public function itemDone($itemtype, $id, $result) $this->nb_done += $number; // If delay is to big, then reload ! - if ($this->timer->getTime() > $this->timeout_delay) { + if (Profiler::getInstance()->getCurrentDuration('MassiveAction:' . $this->identifier) > ($this->timeout_delay * 1000)) { Html::redirect($_SERVER['PHP_SELF'] . '?identifier=' . $this->identifier); } diff --git a/src/Timer.php b/src/Timer.php index f265391e024..bb5aaeaa90c 100644 --- a/src/Timer.php +++ b/src/Timer.php @@ -35,6 +35,7 @@ /** * Timer class for debug and some other cases + * @deprecated 10.1.0 Use Glpi\Debug\Profiler instead */ class Timer { @@ -49,7 +50,7 @@ class Timer */ public function start() { - + Toolbox::deprecated('Timer class is deprecated, use Glpi\Debug\Profiler instead'); $this->timer = microtime(true); return true; } diff --git a/src/Toolbox.php b/src/Toolbox.php index 6b099a5857c..48b9027f001 100644 --- a/src/Toolbox.php +++ b/src/Toolbox.php @@ -490,15 +490,15 @@ public static function logInFile($name, $text, $force = false) * Switch error mode for GLPI * * @param integer|null $mode From Session::*_MODE - * @param boolean|null $debug_sql - * @param boolean|null $debug_vars + * @param boolean|null $removed_param No longer used (Used to be $debug_sql) + * @param boolean|null $removed_param_2 No longer used (Used to be $debug_vars) * @param boolean|null $log_in_files * * @return void * * @since 0.84 **/ - public static function setDebugMode($mode = null, $debug_sql = null, $debug_vars = null, $log_in_files = null) + public static function setDebugMode($mode = null, $removed_param = null, $removed_param_2 = null, $log_in_files = null) { /** @var array $CFG_GLPI */ global $CFG_GLPI; @@ -506,13 +506,6 @@ public static function setDebugMode($mode = null, $debug_sql = null, $debug_vars if (isset($mode)) { $_SESSION['glpi_use_mode'] = $mode; } - //FIXME Deprecate the debug_sql and debug_vars parameters in GLPI 10.1.0 - if (isset($debug_sql)) { - $CFG_GLPI['debug_sql'] = $debug_sql; - } - if (isset($debug_vars)) { - $CFG_GLPI['debug_vars'] = $debug_vars; - } if (isset($log_in_files)) { $CFG_GLPI['use_log_in_files'] = $log_in_files; }