Passed
Push — fix-php-74 ( 9989b6...f6eb65 )
by Alexander
30:32 queued 19s
created

Logger::getDbProfiling()   A

Complexity

Conditions 2
Paths 2

Size

Total Lines 10
Code Lines 6

Duplication

Lines 0
Ratio 0 %

Code Coverage

Tests 0
CRAP Score 6

Importance

Changes 0
Metric Value
cc 2
eloc 6
nc 2
nop 0
dl 0
loc 10
ccs 0
cts 7
cp 0
crap 6
rs 10
c 0
b 0
f 0
1
<?php
2
/**
3
 * @link http://www.yiiframework.com/
4
 * @copyright Copyright (c) 2008 Yii Software LLC
5
 * @license http://www.yiiframework.com/license/
6
 */
7
8
namespace yii\log;
9
10
use Yii;
11
use yii\base\Component;
12
13
/**
14
 * Logger records logged messages in memory and sends them to different targets if [[dispatcher]] is set.
15
 *
16
 * A Logger instance can be accessed via `Yii::getLogger()`. You can call the method [[log()]] to record a single log message.
17
 * For convenience, a set of shortcut methods are provided for logging messages of various severity levels
18
 * via the [[Yii]] class:
19
 *
20
 * - [[Yii::trace()]]
21
 * - [[Yii::error()]]
22
 * - [[Yii::warning()]]
23
 * - [[Yii::info()]]
24
 * - [[Yii::beginProfile()]]
25
 * - [[Yii::endProfile()]]
26
 *
27
 * For more details and usage information on Logger, see the [guide article on logging](guide:runtime-logging).
28
 *
29
 * When the application ends or [[flushInterval]] is reached, Logger will call [[flush()]]
30
 * to send logged messages to different log targets, such as [[FileTarget|file]], [[EmailTarget|email]],
31
 * or [[DbTarget|database]], with the help of the [[dispatcher]].
32
 *
33
 * @property array $dbProfiling The first element indicates the number of SQL statements executed, and the
34
 * second element the total time spent in SQL execution. This property is read-only.
35
 * @property float $elapsedTime The total elapsed time in seconds for current request. This property is
36
 * read-only.
37
 * @property array $profiling The profiling results. Each element is an array consisting of these elements:
38
 * `info`, `category`, `timestamp`, `trace`, `level`, `duration`, `memory`, `memoryDiff`. The `memory` and
39
 * `memoryDiff` values are available since version 2.0.11. This property is read-only.
40
 *
41
 * @author Qiang Xue <[email protected]>
42
 * @since 2.0
43
 */
44
class Logger extends Component
45
{
46
    /**
47
     * Error message level. An error message is one that indicates the abnormal termination of the
48
     * application and may require developer's handling.
49
     */
50
    const LEVEL_ERROR = 0x01;
51
    /**
52
     * Warning message level. A warning message is one that indicates some abnormal happens but
53
     * the application is able to continue to run. Developers should pay attention to this message.
54
     */
55
    const LEVEL_WARNING = 0x02;
56
    /**
57
     * Informational message level. An informational message is one that includes certain information
58
     * for developers to review.
59
     */
60
    const LEVEL_INFO = 0x04;
61
    /**
62
     * Tracing message level. An tracing message is one that reveals the code execution flow.
63
     */
64
    const LEVEL_TRACE = 0x08;
65
    /**
66
     * Profiling message level. This indicates the message is for profiling purpose.
67
     */
68
    const LEVEL_PROFILE = 0x40;
69
    /**
70
     * Profiling message level. This indicates the message is for profiling purpose. It marks the
71
     * beginning of a profiling block.
72
     */
73
    const LEVEL_PROFILE_BEGIN = 0x50;
74
    /**
75
     * Profiling message level. This indicates the message is for profiling purpose. It marks the
76
     * end of a profiling block.
77
     */
78
    const LEVEL_PROFILE_END = 0x60;
79
80
    /**
81
     * @var array logged messages. This property is managed by [[log()]] and [[flush()]].
82
     * Each log message is of the following structure:
83
     *
84
     * ```
85
     * [
86
     *   [0] => message (mixed, can be a string or some complex data, such as an exception object)
87
     *   [1] => level (integer)
88
     *   [2] => category (string)
89
     *   [3] => timestamp (float, obtained by microtime(true))
90
     *   [4] => traces (array, debug backtrace, contains the application code call stacks)
91
     *   [5] => memory usage in bytes (int, obtained by memory_get_usage()), available since version 2.0.11.
92
     * ]
93
     * ```
94
     */
95
    public $messages = [];
96
    /**
97
     * @var int how many messages should be logged before they are flushed from memory and sent to targets.
98
     * Defaults to 1000, meaning the [[flush]] method will be invoked once every 1000 messages logged.
99
     * Set this property to be 0 if you don't want to flush messages until the application terminates.
100
     * This property mainly affects how much memory will be taken by the logged messages.
101
     * A smaller value means less memory, but will increase the execution time due to the overhead of [[flush()]].
102
     */
103
    public $flushInterval = 1000;
104
    /**
105
     * @var int how much call stack information (file name and line number) should be logged for each message.
106
     * If it is greater than 0, at most that number of call stacks will be logged. Note that only application
107
     * call stacks are counted.
108
     */
109
    public $traceLevel = 0;
110
    /**
111
     * @var Dispatcher the message dispatcher
112
     */
113
    public $dispatcher;
114
115
116
    /**
117
     * Initializes the logger by registering [[flush()]] as a shutdown function.
118
     */
119 23
    public function init()
120
    {
121 23
        parent::init();
122 23
        register_shutdown_function(function () {
123
            // make regular flush before other shutdown functions, which allows session data collection and so on
124
            $this->flush();
125
            // make sure log entries written by shutdown functions are also flushed
126
            // ensure "flush()" is called last when there are multiple shutdown functions
127
            register_shutdown_function([$this, 'flush'], true);
128 23
        });
129 23
    }
130
131
    /**
132
     * Logs a message with the given type and category.
133
     * If [[traceLevel]] is greater than 0, additional call stack information about
134
     * the application code will be logged as well.
135
     * @param string|array $message the message to be logged. This can be a simple string or a more
136
     * complex data structure that will be handled by a [[Target|log target]].
137
     * @param int $level the level of the message. This must be one of the following:
138
     * `Logger::LEVEL_ERROR`, `Logger::LEVEL_WARNING`, `Logger::LEVEL_INFO`, `Logger::LEVEL_TRACE`,
139
     * `Logger::LEVEL_PROFILE_BEGIN`, `Logger::LEVEL_PROFILE_END`.
140
     * @param string $category the category of the message.
141
     */
142 2552
    public function log($message, $level, $category = 'application')
143
    {
144 2552
        $time = microtime(true);
145 2552
        $traces = [];
146 2552
        if ($this->traceLevel > 0) {
147
            $count = 0;
148
            $ts = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
149
            array_pop($ts); // remove the last trace since it would be the entry script, not very useful
150
            foreach ($ts as $trace) {
151
                if (isset($trace['file'], $trace['line']) && strpos($trace['file'], YII2_PATH) !== 0) {
152
                    unset($trace['object'], $trace['args']);
153
                    $traces[] = $trace;
154
                    if (++$count >= $this->traceLevel) {
155
                        break;
156
                    }
157
                }
158
            }
159
        }
160 2552
        $this->messages[] = [$message, $level, $category, $time, $traces, memory_get_usage()];
161 2552
        if ($this->flushInterval > 0 && count($this->messages) >= $this->flushInterval) {
162 406
            $this->flush();
163
        }
164 2552
    }
165
166
    /**
167
     * Flushes log messages from memory to targets.
168
     * @param bool $final whether this is a final call during a request.
169
     */
170 413
    public function flush($final = false)
171
    {
172 413
        $messages = $this->messages;
173
        // https://github.com/yiisoft/yii2/issues/5619
174
        // new messages could be logged while the existing ones are being handled by targets
175 413
        $this->messages = [];
176 413
        if ($this->dispatcher instanceof Dispatcher) {
0 ignored issues
show
introduced by
$this->dispatcher is always a sub-type of yii\log\Dispatcher.
Loading history...
177 413
            $this->dispatcher->dispatch($messages, $final);
178
        }
179 413
    }
180
181
    /**
182
     * Returns the total elapsed time since the start of the current request.
183
     * This method calculates the difference between now and the timestamp
184
     * defined by constant `YII_BEGIN_TIME` which is evaluated at the beginning
185
     * of [[\yii\BaseYii]] class file.
186
     * @return float the total elapsed time in seconds for current request.
187
     */
188
    public function getElapsedTime()
189
    {
190
        return microtime(true) - YII_BEGIN_TIME;
191
    }
192
193
    /**
194
     * Returns the profiling results.
195
     *
196
     * By default, all profiling results will be returned. You may provide
197
     * `$categories` and `$excludeCategories` as parameters to retrieve the
198
     * results that you are interested in.
199
     *
200
     * @param array $categories list of categories that you are interested in.
201
     * You can use an asterisk at the end of a category to do a prefix match.
202
     * For example, 'yii\db\*' will match categories starting with 'yii\db\',
203
     * such as 'yii\db\Connection'.
204
     * @param array $excludeCategories list of categories that you want to exclude
205
     * @return array the profiling results. Each element is an array consisting of these elements:
206
     * `info`, `category`, `timestamp`, `trace`, `level`, `duration`, `memory`, `memoryDiff`.
207
     * The `memory` and `memoryDiff` values are available since version 2.0.11.
208
     */
209
    public function getProfiling($categories = [], $excludeCategories = [])
210
    {
211
        $timings = $this->calculateTimings($this->messages);
212
        if (empty($categories) && empty($excludeCategories)) {
213
            return $timings;
214
        }
215
216
        foreach ($timings as $i => $timing) {
217
            $matched = empty($categories);
218
            foreach ($categories as $category) {
219
                $prefix = rtrim($category, '*');
220
                if (($timing['category'] === $category || $prefix !== $category) && strpos($timing['category'], $prefix) === 0) {
221
                    $matched = true;
222
                    break;
223
                }
224
            }
225
226
            if ($matched) {
227
                foreach ($excludeCategories as $category) {
228
                    $prefix = rtrim($category, '*');
229
                    foreach ($timings as $i => $timing) {
0 ignored issues
show
Comprehensibility Bug introduced by
$timing is overwriting a variable from outer foreach loop.
Loading history...
Comprehensibility Bug introduced by
$i is overwriting a variable from outer foreach loop.
Loading history...
230
                        if (($timing['category'] === $category || $prefix !== $category) && strpos($timing['category'], $prefix) === 0) {
231
                            $matched = false;
232
                            break;
233
                        }
234
                    }
235
                }
236
            }
237
238
            if (!$matched) {
239
                unset($timings[$i]);
240
            }
241
        }
242
243
        return array_values($timings);
244
    }
245
246
    /**
247
     * Returns the statistical results of DB queries.
248
     * The results returned include the number of SQL statements executed and
249
     * the total time spent.
250
     * @return array the first element indicates the number of SQL statements executed,
251
     * and the second element the total time spent in SQL execution.
252
     */
253
    public function getDbProfiling()
254
    {
255
        $timings = $this->getProfiling(['yii\db\Command::query', 'yii\db\Command::execute']);
256
        $count = count($timings);
257
        $time = 0;
258
        foreach ($timings as $timing) {
259
            $time += $timing['duration'];
260
        }
261
262
        return [$count, $time];
263
    }
264
265
    /**
266
     * Calculates the elapsed time for the given log messages.
267
     * @param array $messages the log messages obtained from profiling
268
     * @return array timings. Each element is an array consisting of these elements:
269
     * `info`, `category`, `timestamp`, `trace`, `level`, `duration`, `memory`, `memoryDiff`.
270
     * The `memory` and `memoryDiff` values are available since version 2.0.11.
271
     */
272
    public function calculateTimings($messages)
273
    {
274
        $timings = [];
275
        $stack = [];
276
277
        foreach ($messages as $i => $log) {
278
            list($token, $level, $category, $timestamp, $traces) = $log;
279
            $memory = isset($log[5]) ? $log[5] : 0;
280
            $log[6] = $i;
281
            $hash = md5(json_encode($token));
282
            if ($level == self::LEVEL_PROFILE_BEGIN) {
283
                $stack[$hash] = $log;
284
            } elseif ($level == self::LEVEL_PROFILE_END) {
285
                if (isset($stack[$hash])) {
286
                    $timings[$stack[$hash][6]] = [
287
                        'info' => $stack[$hash][0],
288
                        'category' => $stack[$hash][2],
289
                        'timestamp' => $stack[$hash][3],
290
                        'trace' => $stack[$hash][4],
291
                        'level' => count($stack) - 1,
292
                        'duration' => $timestamp - $stack[$hash][3],
293
                        'memory' => $memory,
294
                        'memoryDiff' => $memory - (isset($stack[$hash][5]) ? $stack[$hash][5] : 0),
295
                    ];
296
                    unset($stack[$hash]);
297
                }
298
            }
299
        }
300
301
        ksort($timings);
302
303
        return array_values($timings);
304
    }
305
306
307
    /**
308
     * Returns the text display of the specified level.
309
     * @param int $level the message level, e.g. [[LEVEL_ERROR]], [[LEVEL_WARNING]].
310
     * @return string the text display of the level
311
     */
312 2
    public static function getLevelName($level)
313
    {
314 2
        static $levels = [
315
            self::LEVEL_ERROR => 'error',
316
            self::LEVEL_WARNING => 'warning',
317
            self::LEVEL_INFO => 'info',
318
            self::LEVEL_TRACE => 'trace',
319
            self::LEVEL_PROFILE_BEGIN => 'profile begin',
320
            self::LEVEL_PROFILE_END => 'profile end',
321
            self::LEVEL_PROFILE => 'profile',
322
        ];
323
324 2
        return isset($levels[$level]) ? $levels[$level] : 'unknown';
325
    }
326
}
327