511 lines
18 KiB
PHP
511 lines
18 KiB
PHP
|
<?php
|
|||
|
|
/**
|
|||
|
|
* Real-time SQL Query Logger with PRE-execution tracking
|
|||
|
|
*/
|
|||
|
|
|
|||
|
|
class RealtimeSqlLogger {
|
|||
|
|
private static $instance;
|
|||
|
|
private $log_file;
|
|||
|
|
private $request_id;
|
|||
|
|
private $start_time;
|
|||
|
|
private $pending_queries = [];
|
|||
|
|
private $log_enabled = true;
|
|||
|
|
private $current_location = 'unknown';
|
|||
|
|
|
|||
|
|
public static function get_instance() {
|
|||
|
|
if (null === self::$instance) {
|
|||
|
|
self::$instance = new self();
|
|||
|
|
}
|
|||
|
|
return self::$instance;
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
private function __construct() {
|
|||
|
|
$this->log_file = WP_CONTENT_DIR . '/sql-debug.log';
|
|||
|
|
$this->request_id = uniqid('req_', true);
|
|||
|
|
$this->start_time = microtime(true);
|
|||
|
|
|
|||
|
|
$this->init_log_file();
|
|||
|
|
$this->init();
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
private function init_log_file() {
|
|||
|
|
if (!is_writable(WP_CONTENT_DIR)) {
|
|||
|
|
$this->log_enabled = false;
|
|||
|
|
error_log('Директория wp-content недоступна для записи');
|
|||
|
|
return;
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
if (!file_exists($this->log_file)) {
|
|||
|
|
if (@touch($this->log_file)) {
|
|||
|
|
@chmod($this->log_file, 0644);
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
// Очищаем файл при каждой инициализации
|
|||
|
|
@file_put_contents($this->log_file, '');
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
private function init() {
|
|||
|
|
if (!$this->log_enabled) return;
|
|||
|
|
|
|||
|
|
// Трекинг местоположения в WordPress
|
|||
|
|
$this->setup_location_tracking();
|
|||
|
|
|
|||
|
|
// Перехватываем запрос ДО выполнения
|
|||
|
|
add_filter('query', [$this, 'log_query_before_execution'], 1, 1);
|
|||
|
|
|
|||
|
|
// Логируем результат выполнения
|
|||
|
|
add_filter('query', [$this, 'log_query_after_execution'], 9999, 2);
|
|||
|
|
|
|||
|
|
// Логируем ошибки запросов
|
|||
|
|
add_action('wpdb_error', [$this, 'log_query_error'], 10, 2);
|
|||
|
|
|
|||
|
|
add_action('shutdown', [$this, 'log_pending_queries'], 9999);
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
/**
|
|||
|
|
* Настраиваем трекинг местоположения в WordPress
|
|||
|
|
*/
|
|||
|
|
private function setup_location_tracking() {
|
|||
|
|
// Основные хуки WordPress для определения местоположения
|
|||
|
|
$location_hooks = [
|
|||
|
|
'plugins_loaded' => 'PLUGINS_LOADED',
|
|||
|
|
'setup_theme' => 'SETUP_THEME',
|
|||
|
|
'after_setup_theme' => 'AFTER_SETUP_THEME',
|
|||
|
|
'init' => 'INIT',
|
|||
|
|
'wp_loaded' => 'WP_LOADED',
|
|||
|
|
'parse_query' => 'PARSE_QUERY',
|
|||
|
|
'pre_get_posts' => 'PRE_GET_POSTS',
|
|||
|
|
'wp' => 'WP_MAIN_QUERY',
|
|||
|
|
'template_redirect' => 'TEMPLATE_REDIRECT',
|
|||
|
|
'get_header' => 'HEADER',
|
|||
|
|
'wp_head' => 'WP_HEAD',
|
|||
|
|
'loop_start' => 'LOOP_START',
|
|||
|
|
'the_post' => 'THE_POST',
|
|||
|
|
'loop_end' => 'LOOP_END',
|
|||
|
|
'get_sidebar' => 'SIDEBAR',
|
|||
|
|
'get_footer' => 'FOOTER',
|
|||
|
|
'wp_footer' => 'WP_FOOTER',
|
|||
|
|
'shutdown' => 'SHUTDOWN'
|
|||
|
|
];
|
|||
|
|
|
|||
|
|
foreach ($location_hooks as $hook => $location) {
|
|||
|
|
add_action($hook, function() use ($location) {
|
|||
|
|
$this->current_location = $location;
|
|||
|
|
$this->log_message("📍 LOCATION: {$location}", 'LOCATION', false);
|
|||
|
|
}, 1);
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
// Специальные хуки для контента
|
|||
|
|
add_action('the_content', function($content) {
|
|||
|
|
$this->current_location = 'THE_CONTENT';
|
|||
|
|
return $content;
|
|||
|
|
});
|
|||
|
|
|
|||
|
|
add_action('the_title', function($title) {
|
|||
|
|
$this->current_location = 'THE_TITLE';
|
|||
|
|
return $title;
|
|||
|
|
});
|
|||
|
|
|
|||
|
|
add_action('the_excerpt', function($excerpt) {
|
|||
|
|
$this->current_location = 'THE_EXCERPT';
|
|||
|
|
return $excerpt;
|
|||
|
|
});
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
/**
|
|||
|
|
* Перехватываем запрос ДО выполнения
|
|||
|
|
*/
|
|||
|
|
public function log_query_before_execution($query) {
|
|||
|
|
if (!$this->log_enabled) return $query;
|
|||
|
|
|
|||
|
|
$trimmed = trim($query);
|
|||
|
|
if (empty($trimmed)) return $query;
|
|||
|
|
|
|||
|
|
$query_hash = md5($query . microtime(true));
|
|||
|
|
$backtrace_info = $this->get_detailed_caller_info();
|
|||
|
|
|
|||
|
|
// Сохраняем запрос как pending
|
|||
|
|
$this->pending_queries[$query_hash] = [
|
|||
|
|
'query' => $query,
|
|||
|
|
'start_time' => microtime(true),
|
|||
|
|
'backtrace' => $backtrace_info['short'],
|
|||
|
|
'detailed_backtrace' => $backtrace_info['full'],
|
|||
|
|
'component' => $this->get_component_info($backtrace_info['file']),
|
|||
|
|
'location' => $this->current_location,
|
|||
|
|
'status' => 'PENDING'
|
|||
|
|
];
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
"🚦 QUERY QUEUED: " . $this->shorten_query($query),
|
|||
|
|
'SQL-QUEUE',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
" 📍 Source: " . $backtrace_info['short'],
|
|||
|
|
'SQL-QUEUE',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
" 🏷️ Component: " . $this->pending_queries[$query_hash]['component'],
|
|||
|
|
'SQL-QUEUE',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
" 🏠 Location: " . $this->current_location,
|
|||
|
|
'SQL-QUEUE',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
return $query;
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
/**
|
|||
|
|
* Логируем запрос ПОСЛЕ выполнения
|
|||
|
|
*/
|
|||
|
|
public function log_query_after_execution($query, $result = null) {
|
|||
|
|
if (!$this->log_enabled) return $query;
|
|||
|
|
|
|||
|
|
$trimmed = trim($query);
|
|||
|
|
if (empty($trimmed)) return $query;
|
|||
|
|
|
|||
|
|
$query_hash = md5($query . microtime(true));
|
|||
|
|
$execution_time = 0;
|
|||
|
|
$caller_info = '';
|
|||
|
|
$component_info = '';
|
|||
|
|
$location_info = '';
|
|||
|
|
|
|||
|
|
// Находим соответствующий pending запрос
|
|||
|
|
foreach ($this->pending_queries as $hash => $pending) {
|
|||
|
|
if ($pending['query'] === $query) {
|
|||
|
|
$execution_time = microtime(true) - $pending['start_time'];
|
|||
|
|
$this->pending_queries[$hash]['status'] = 'COMPLETED';
|
|||
|
|
$this->pending_queries[$hash]['execution_time'] = $execution_time;
|
|||
|
|
$caller_info = $pending['backtrace'];
|
|||
|
|
$component_info = $pending['component'];
|
|||
|
|
$location_info = $pending['location'];
|
|||
|
|
break;
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
$status = $result === false ? 'FAILED' : 'COMPLETED';
|
|||
|
|
$time_ms = round($execution_time * 1000, 2);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
"✅ QUERY {$status}: {$time_ms}ms - " . $this->shorten_query($query),
|
|||
|
|
$status === 'FAILED' ? 'SQL-ERROR' : 'SQL-DONE',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
" 📍 Source: " . $caller_info,
|
|||
|
|
$status === 'FAILED' ? 'SQL-ERROR' : 'SQL-DONE',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
" 🏷️ Component: " . $component_info,
|
|||
|
|
$status === 'FAILED' ? 'SQL-ERROR' : 'SQL-DONE',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
" 🏠 Location: " . $location_info,
|
|||
|
|
$status === 'FAILED' ? 'SQL-ERROR' : 'SQL-DONE',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
// Для медленных запросов добавляем дополнительную информацию
|
|||
|
|
if ($time_ms > 100 && $status !== 'FAILED') {
|
|||
|
|
$this->log_message(
|
|||
|
|
" ⚠️ SLOW QUERY: {$time_ms}ms - consider optimization",
|
|||
|
|
'SQL-SLOW',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
return $query;
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
/**
|
|||
|
|
* Логируем ошибки запросов
|
|||
|
|
*/
|
|||
|
|
public function log_query_error($error, $query) {
|
|||
|
|
if (!$this->log_enabled) return;
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
"❌ QUERY ERROR: " . $error,
|
|||
|
|
'SQL-ERROR',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
" 💥 Failed query: " . $this->shorten_query($query),
|
|||
|
|
'SQL-ERROR',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
// Находим информацию о вызывающем коде для ошибочного запроса
|
|||
|
|
foreach ($this->pending_queries as $pending) {
|
|||
|
|
if ($pending['query'] === $query) {
|
|||
|
|
$this->log_message(
|
|||
|
|
" 📍 Source: " . $pending['backtrace'],
|
|||
|
|
'SQL-ERROR',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
" 🏷️ Component: " . $pending['component'],
|
|||
|
|
'SQL-ERROR',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
" 🏠 Location: " . $pending['location'],
|
|||
|
|
'SQL-ERROR',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
break;
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
/**
|
|||
|
|
* Логируем зависшие запросы
|
|||
|
|
*/
|
|||
|
|
public function log_pending_queries() {
|
|||
|
|
if (!$this->log_enabled || empty($this->pending_queries)) return;
|
|||
|
|
|
|||
|
|
$current_time = microtime(true);
|
|||
|
|
$hung_queries = 0;
|
|||
|
|
|
|||
|
|
foreach ($this->pending_queries as $hash => $query_info) {
|
|||
|
|
if ($query_info['status'] === 'PENDING') {
|
|||
|
|
$hang_time = round(($current_time - $query_info['start_time']) * 1000, 2);
|
|||
|
|
$hung_queries++;
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
"⚠️ HUNG QUERY: {$hang_time}ms - " . $this->shorten_query($query_info['query']),
|
|||
|
|
'SQL-HUNG',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
" 📍 Source: " . $query_info['backtrace'],
|
|||
|
|
'SQL-HUNG',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
" 🏷️ Component: " . $query_info['component'],
|
|||
|
|
'SQL-HUNG',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
" 🏠 Location: " . $query_info['location'],
|
|||
|
|
'SQL-HUNG',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
" 🔍 Full backtrace:\n" . $query_info['detailed_backtrace'],
|
|||
|
|
'SQL-HUNG',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
if ($hung_queries > 0) {
|
|||
|
|
$this->log_message(
|
|||
|
|
"🔴 Found {$hung_queries} hung queries!",
|
|||
|
|
'SQL-HUNG',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
// Логируем статистику по всем запросам
|
|||
|
|
$this->log_query_statistics();
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
/**
|
|||
|
|
* Логируем статистику выполнения запросов
|
|||
|
|
*/
|
|||
|
|
private function log_query_statistics() {
|
|||
|
|
$total_queries = count($this->pending_queries);
|
|||
|
|
$completed_queries = 0;
|
|||
|
|
$failed_queries = 0;
|
|||
|
|
$total_time = 0;
|
|||
|
|
|
|||
|
|
$queries_by_location = [];
|
|||
|
|
$queries_by_component = [];
|
|||
|
|
|
|||
|
|
foreach ($this->pending_queries as $query) {
|
|||
|
|
// Статистика по местоположению
|
|||
|
|
$location = $query['location'];
|
|||
|
|
if (!isset($queries_by_location[$location])) {
|
|||
|
|
$queries_by_location[$location] = 0;
|
|||
|
|
}
|
|||
|
|
$queries_by_location[$location]++;
|
|||
|
|
|
|||
|
|
// Статистика по компонентам
|
|||
|
|
$component = $query['component'];
|
|||
|
|
if (!isset($queries_by_component[$component])) {
|
|||
|
|
$queries_by_component[$component] = 0;
|
|||
|
|
}
|
|||
|
|
$queries_by_component[$component]++;
|
|||
|
|
|
|||
|
|
if ($query['status'] === 'COMPLETED') {
|
|||
|
|
$completed_queries++;
|
|||
|
|
$total_time += $query['execution_time'] ?? 0;
|
|||
|
|
} elseif ($query['status'] === 'FAILED') {
|
|||
|
|
$failed_queries++;
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
$avg_time = $completed_queries > 0 ? round(($total_time / $completed_queries) * 1000, 2) : 0;
|
|||
|
|
|
|||
|
|
$this->log_message(
|
|||
|
|
"📊 STATS: Total: {$total_queries} | Completed: {$completed_queries} | " .
|
|||
|
|
"Failed: {$failed_queries} | Avg: {$avg_time}ms",
|
|||
|
|
'STATS',
|
|||
|
|
false
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
// Статистика по местоположению
|
|||
|
|
if (!empty($queries_by_location)) {
|
|||
|
|
$this->log_message("📊 QUERIES BY LOCATION:", 'STATS', false);
|
|||
|
|
arsort($queries_by_location);
|
|||
|
|
foreach ($queries_by_location as $location => $count) {
|
|||
|
|
$this->log_message(" {$location}: {$count} queries", 'STATS', false);
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
// Статистика по компонентам
|
|||
|
|
if (!empty($queries_by_component)) {
|
|||
|
|
$this->log_message("📊 QUERIES BY COMPONENT:", 'STATS', false);
|
|||
|
|
arsort($queries_by_component);
|
|||
|
|
foreach ($queries_by_component as $component => $count) {
|
|||
|
|
$this->log_message(" {$component}: {$count} queries", 'STATS', false);
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
private function log_message($message, $level = 'INFO', $check_enabled = true) {
|
|||
|
|
if ($check_enabled && !$this->log_enabled) return;
|
|||
|
|
|
|||
|
|
$timestamp = microtime(true);
|
|||
|
|
$elapsed = round(($timestamp - $this->start_time) * 1000, 2);
|
|||
|
|
|
|||
|
|
$log = sprintf(
|
|||
|
|
"[%s] %s | %6.2fms | %-12s | %s\n",
|
|||
|
|
date('H:i:s'),
|
|||
|
|
substr($this->request_id, -6),
|
|||
|
|
$elapsed,
|
|||
|
|
$level,
|
|||
|
|
$message
|
|||
|
|
);
|
|||
|
|
|
|||
|
|
@file_put_contents($this->log_file, $log, FILE_APPEND | LOCK_EX);
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
/**
|
|||
|
|
* Получаем детальную информацию о вызывающем коде
|
|||
|
|
*/
|
|||
|
|
private function get_detailed_caller_info() {
|
|||
|
|
$backtrace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 15);
|
|||
|
|
$short_info = 'unknown';
|
|||
|
|
$full_info = '';
|
|||
|
|
$file_path = '';
|
|||
|
|
|
|||
|
|
foreach ($backtrace as $index => $trace) {
|
|||
|
|
if (isset($trace['file']) &&
|
|||
|
|
!str_contains($trace['file'], 'wp-includes') &&
|
|||
|
|
!str_contains($trace['file'], 'wp-admin')) {
|
|||
|
|
|
|||
|
|
$file = basename($trace['file']);
|
|||
|
|
$line = $trace['line'] ?? 'unknown';
|
|||
|
|
$function = $trace['function'] ?? 'unknown';
|
|||
|
|
|
|||
|
|
if ($short_info === 'unknown') {
|
|||
|
|
$short_info = "{$file}:{$line} ({$function})";
|
|||
|
|
$file_path = $trace['file'];
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
$full_info .= sprintf("#%d %s(%d): %s()\n",
|
|||
|
|
$index,
|
|||
|
|
$trace['file'],
|
|||
|
|
$trace['line'] ?? 0,
|
|||
|
|
$function
|
|||
|
|
);
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
return [
|
|||
|
|
'short' => $short_info,
|
|||
|
|
'full' => $full_info ?: 'No backtrace available',
|
|||
|
|
'file' => $file_path
|
|||
|
|
];
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
/**
|
|||
|
|
* Определяем компонент (плагин/тема) по пути файла
|
|||
|
|
*/
|
|||
|
|
private function get_component_info($file_path) {
|
|||
|
|
if (empty($file_path)) return 'unknown';
|
|||
|
|
|
|||
|
|
$abspath = ABSPATH;
|
|||
|
|
|
|||
|
|
// Определяем тип компонента
|
|||
|
|
if (str_contains($file_path, WP_PLUGIN_DIR)) {
|
|||
|
|
$relative_path = str_replace(WP_PLUGIN_DIR . '/', '', $file_path);
|
|||
|
|
$parts = explode('/', $relative_path);
|
|||
|
|
return 'Plugin: ' . $parts[0];
|
|||
|
|
} elseif (str_contains($file_path, get_template_directory())) {
|
|||
|
|
$theme = wp_get_theme();
|
|||
|
|
return 'Theme: ' . $theme->get('Name');
|
|||
|
|
} elseif (str_contains($file_path, get_stylesheet_directory())) {
|
|||
|
|
$theme = wp_get_theme();
|
|||
|
|
return 'Child Theme: ' . $theme->get('Name');
|
|||
|
|
} elseif (str_contains($file_path, $abspath . 'wp-content/mu-plugins')) {
|
|||
|
|
return 'MU-Plugin';
|
|||
|
|
} elseif (str_contains($file_path, $abspath . 'wp-content')) {
|
|||
|
|
return 'Other (wp-content)';
|
|||
|
|
} elseif (str_contains($file_path, $abspath)) {
|
|||
|
|
return 'WordPress Core';
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
return 'External';
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
private function shorten_query($query, $length = 120) {
|
|||
|
|
$trimmed = trim($query);
|
|||
|
|
if (strlen($trimmed) <= $length) return $trimmed;
|
|||
|
|
|
|||
|
|
return substr($trimmed, 0, $length) . '...';
|
|||
|
|
}
|
|||
|
|
}
|
|||
|
|
|
|||
|
|
// Инициализируем логгер
|
|||
|
|
//if (defined('WP_DEBUG') && WP_DEBUG) {
|
|||
|
|
RealtimeSqlLogger::get_instance();
|
|||
|
|
//}
|
|||
|
|
|
|||
|
|
// Функция для просмотра текущего состояния
|
|||
|
|
add_action('wp_footer', 'show_sql_debug_info', 9999);
|
|||
|
|
function show_sql_debug_info() {
|
|||
|
|
if (!current_user_can('administrator')) return;
|
|||
|
|
|
|||
|
|
$log_file = WP_CONTENT_DIR . '/sql-debug.log';
|
|||
|
|
|
|||
|
|
if (file_exists($log_file)) {
|
|||
|
|
$log_content = file_get_contents($log_file);
|
|||
|
|
echo '<div style="background:#1e1e1e;padding:20px;margin:20px;border:1px solid #444;font-family:monospace;font-size:11px;max-height:400px;overflow:auto;color:#fff;">';
|
|||
|
|
echo '<h3 style="color:#fff;">🎯 SQL Debug Log (Live)</h3>';
|
|||
|
|
echo '<pre style="color:#ccc;line-height:1.4;">' . htmlspecialchars($log_content) . '</pre>';
|
|||
|
|
echo '</div>';
|
|||
|
|
}
|
|||
|
|
}
|