|
1
|
|
|
<?php |
|
2
|
|
|
|
|
3
|
|
|
/** |
|
4
|
|
|
* File containing the Persistence Cache SPI logger class. |
|
5
|
|
|
* |
|
6
|
|
|
* @copyright Copyright (C) eZ Systems AS. All rights reserved. |
|
7
|
|
|
* @license For full copyright and license information view LICENSE file distributed with this source code. |
|
8
|
|
|
*/ |
|
9
|
|
|
declare(strict_types=1); |
|
10
|
|
|
|
|
11
|
|
|
namespace eZ\Publish\Core\Persistence\Cache; |
|
12
|
|
|
|
|
13
|
|
|
/** |
|
14
|
|
|
* Log un-cached & cached use of SPI Persistence. |
|
15
|
|
|
*/ |
|
16
|
|
|
class PersistenceLogger |
|
17
|
|
|
{ |
|
18
|
|
|
const NAME = 'PersistenceLogger'; |
|
19
|
|
|
|
|
20
|
|
|
/** |
|
21
|
|
|
* @var int[] |
|
22
|
|
|
*/ |
|
23
|
|
|
protected $stats = [ |
|
24
|
|
|
'uncached' => 0, |
|
25
|
|
|
'miss' => 0, |
|
26
|
|
|
'hit' => 0, |
|
27
|
|
|
'memory' => 0, |
|
28
|
|
|
]; |
|
29
|
|
|
|
|
30
|
|
|
/** |
|
31
|
|
|
* @var bool |
|
32
|
|
|
*/ |
|
33
|
|
|
protected $logCalls = true; |
|
34
|
|
|
|
|
35
|
|
|
/** |
|
36
|
|
|
* @var array |
|
37
|
|
|
*/ |
|
38
|
|
|
protected $calls = []; |
|
39
|
|
|
|
|
40
|
|
|
/** |
|
41
|
|
|
* @var array |
|
42
|
|
|
*/ |
|
43
|
|
|
protected $unCachedHandlers = []; |
|
44
|
|
|
|
|
45
|
|
|
/** |
|
46
|
|
|
* @param bool $logCalls Flag to enable logging of calls or not, provides extra debug info about calls made to SPI |
|
47
|
|
|
* level, including where they come form. However this uses quite a bit of memory. |
|
48
|
|
|
*/ |
|
49
|
|
|
public function __construct(bool $logCalls = true) |
|
50
|
|
|
{ |
|
51
|
|
|
$this->logCalls = $logCalls; |
|
52
|
|
|
} |
|
53
|
|
|
|
|
54
|
|
|
/** |
|
55
|
|
|
* Log uncached SPI calls with method name and arguments. |
|
56
|
|
|
* |
|
57
|
|
|
* NOTE: As of 7.5 this method is meant for logging calls to uncached spi method calls, |
|
58
|
|
|
* for cache miss calls to cached SPI methods migrate to use {@see logCacheMiss()}. |
|
59
|
|
|
* |
|
60
|
|
|
* @param string $method |
|
61
|
|
|
* @param array $arguments |
|
62
|
|
|
*/ |
|
63
|
|
|
public function logCall(string $method, array $arguments = []): void |
|
64
|
|
|
{ |
|
65
|
|
|
++$this->stats['uncached']; |
|
66
|
|
|
if (!$this->logCalls) { |
|
67
|
|
|
return; |
|
68
|
|
|
} |
|
69
|
|
|
|
|
70
|
|
|
$this->collectCacheCallData( |
|
71
|
|
|
$method, |
|
72
|
|
|
$arguments, |
|
73
|
|
|
\array_slice( |
|
74
|
|
|
\debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 7), |
|
75
|
|
|
2 |
|
76
|
|
|
), |
|
77
|
|
|
'uncached' |
|
78
|
|
|
); |
|
79
|
|
|
} |
|
80
|
|
|
|
|
81
|
|
|
/** |
|
82
|
|
|
* Log Cache miss, gets info it needs by backtrace if needed. |
|
83
|
|
|
* |
|
84
|
|
|
* @since 7.5 |
|
85
|
|
|
* |
|
86
|
|
|
* @param array $arguments |
|
87
|
|
|
* @param int $traceOffset |
|
88
|
|
|
*/ |
|
89
|
|
|
public function logCacheMiss(array $arguments = [], int $traceOffset = 2): void |
|
90
|
|
|
{ |
|
91
|
|
|
++$this->stats['miss']; |
|
92
|
|
|
if (!$this->logCalls) { |
|
93
|
|
|
return; |
|
94
|
|
|
} |
|
95
|
|
|
|
|
96
|
|
|
$trace = \debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 7 + $traceOffset); |
|
97
|
|
|
$this->collectCacheCallData( |
|
98
|
|
|
$trace[$traceOffset - 1]['class'] . '::' . $trace[$traceOffset - 1]['function'], |
|
99
|
|
|
$arguments, |
|
100
|
|
|
\array_slice($trace, $traceOffset), |
|
101
|
|
|
'miss' |
|
102
|
|
|
); |
|
103
|
|
|
} |
|
104
|
|
|
|
|
105
|
|
|
/** |
|
106
|
|
|
* Log a Cache hit, gets info it needs by backtrace if needed. |
|
107
|
|
|
* |
|
108
|
|
|
* @since 7.5 |
|
109
|
|
|
* |
|
110
|
|
|
* @param array $arguments |
|
111
|
|
|
* @param int $traceOffset |
|
112
|
|
|
* @param bool $inMemory Denotes is cache hit was from memory (php variable), as opposed to from cache pool which |
|
113
|
|
|
* is usually disk or remote cache service. |
|
114
|
|
|
*/ |
|
115
|
|
|
public function logCacheHit(array $arguments = [], int $traceOffset = 2, bool $inMemory = false): void |
|
116
|
|
|
{ |
|
117
|
|
|
if ($inMemory) { |
|
118
|
|
|
++$this->stats['memory']; |
|
119
|
|
|
} else { |
|
120
|
|
|
++$this->stats['hit']; |
|
121
|
|
|
} |
|
122
|
|
|
|
|
123
|
|
|
if (!$this->logCalls) { |
|
124
|
|
|
return; |
|
125
|
|
|
} |
|
126
|
|
|
|
|
127
|
|
|
$trace = \debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 7 + $traceOffset); |
|
128
|
|
|
$this->collectCacheCallData( |
|
129
|
|
|
$trace[$traceOffset - 1]['class'] . '::' . $trace[$traceOffset - 1]['function'], |
|
130
|
|
|
$arguments, |
|
131
|
|
|
\array_slice($trace, $traceOffset), |
|
132
|
|
|
$inMemory ? 'memory' : 'hit' |
|
133
|
|
|
); |
|
134
|
|
|
} |
|
135
|
|
|
|
|
136
|
|
|
/** |
|
137
|
|
|
* Collection method for {@see logCacheHit()}, {@see logCacheMiss()} & {@see logCall()}. |
|
138
|
|
|
* |
|
139
|
|
|
* @param $method |
|
140
|
|
|
* @param array $arguments |
|
141
|
|
|
* @param array $trimmedBacktrace |
|
142
|
|
|
* @param string $type |
|
143
|
|
|
*/ |
|
144
|
|
|
private function collectCacheCallData($method, array $arguments, array $trimmedBacktrace, string $type): void |
|
145
|
|
|
{ |
|
146
|
|
|
// simplest/fastests hash possible to identify if we have already collected this before to save on memory use |
|
147
|
|
|
$callHash = \hash('adler32', $method . \serialize($arguments)); |
|
148
|
|
|
if (empty($this->calls[$callHash])) { |
|
149
|
|
|
$this->calls[$callHash] = [ |
|
150
|
|
|
'method' => $method, |
|
151
|
|
|
'arguments' => $arguments, |
|
152
|
|
|
'stats' => [ |
|
153
|
|
|
'uncached' => 0, |
|
154
|
|
|
'miss' => 0, |
|
155
|
|
|
'hit' => 0, |
|
156
|
|
|
'memory' => 0, |
|
157
|
|
|
], |
|
158
|
|
|
'traces' => [], |
|
159
|
|
|
]; |
|
160
|
|
|
} |
|
161
|
|
|
++$this->calls[$callHash]['stats'][$type]; |
|
162
|
|
|
|
|
163
|
|
|
// @todo If we want/need to save more memory we can consider making an value object holding "trace", and share |
|
164
|
|
|
// the object across all calls having same trace (quite often the case). |
|
165
|
|
|
$trace = $this->getSimpleCallTrace($trimmedBacktrace); |
|
166
|
|
|
$traceHash = \hash('adler32', \implode($trace)); |
|
167
|
|
|
if (empty($this->calls[$callHash]['traces'][$traceHash])) { |
|
168
|
|
|
$this->calls[$callHash]['traces'][$traceHash] = [ |
|
169
|
|
|
'trace' => $trace, |
|
170
|
|
|
'count' => 0, |
|
171
|
|
|
]; |
|
172
|
|
|
} |
|
173
|
|
|
++$this->calls[$callHash]['traces'][$traceHash]['count']; |
|
174
|
|
|
} |
|
175
|
|
|
|
|
176
|
|
|
/** |
|
177
|
|
|
* Simplify trace to an array of strings. |
|
178
|
|
|
* |
|
179
|
|
|
* Skipps any traces from Syfony proxies or closures to make trace as readable as possible in as few lines as |
|
180
|
|
|
* possible. And point is to identify which code outside kernel is triggering the SPI call, so trace stops one |
|
181
|
|
|
* call after namespace is no longer in eZ\Publish\Core\. |
|
182
|
|
|
* |
|
183
|
|
|
* @param array $backtrace Partial backtrace from |debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS) or similar. |
|
184
|
|
|
* |
|
185
|
|
|
* @return string[] |
|
186
|
|
|
*/ |
|
187
|
|
|
private function getSimpleCallTrace(array $backtrace): array |
|
188
|
|
|
{ |
|
189
|
|
|
$calls = []; |
|
190
|
|
|
foreach ($backtrace as $call) { |
|
191
|
|
|
if (!isset($call['class'][2]) || ($call['class'][2] !== '\\' && \strpos($call['class'], '\\') === false)) { |
|
192
|
|
|
// skip if class has no namespace (Symfony lazy proxy or plain function) |
|
193
|
|
|
continue; |
|
194
|
|
|
} |
|
195
|
|
|
|
|
196
|
|
|
$calls[] = $call['class'] . $call['type'] . $call['function'] . '()'; |
|
197
|
|
|
|
|
198
|
|
|
// Break out as soon as we have listed 1 class outside of kernel |
|
199
|
|
|
if ($call['class'][0] !== 'e' && \strpos($call['class'], 'eZ\\Publish\\Core\\') !== 0) { |
|
200
|
|
|
break; |
|
201
|
|
|
} |
|
202
|
|
|
} |
|
203
|
|
|
|
|
204
|
|
|
return $calls; |
|
205
|
|
|
} |
|
206
|
|
|
|
|
207
|
|
|
/** |
|
208
|
|
|
* Log un-cached handler being loaded. |
|
209
|
|
|
* |
|
210
|
|
|
* @param string $handler |
|
211
|
|
|
*/ |
|
212
|
|
|
public function logUnCachedHandler(string $handler): void |
|
213
|
|
|
{ |
|
214
|
|
|
if (!isset($this->unCachedHandlers[$handler])) { |
|
215
|
|
|
$this->unCachedHandlers[$handler] = 0; |
|
216
|
|
|
} |
|
217
|
|
|
++$this->unCachedHandlers[$handler]; |
|
218
|
|
|
} |
|
219
|
|
|
|
|
220
|
|
|
public function getName(): string |
|
221
|
|
|
{ |
|
222
|
|
|
return self::NAME; |
|
223
|
|
|
} |
|
224
|
|
|
|
|
225
|
|
|
/** |
|
226
|
|
|
* Counts the total of spi uncached call (cache miss and uncached calls). |
|
227
|
|
|
* |
|
228
|
|
|
* @deprecated Since 7.5, use getStats(). |
|
229
|
|
|
*/ |
|
230
|
|
|
public function getCount(): int |
|
231
|
|
|
{ |
|
232
|
|
|
return $this->stats['uncached'] + $this->stats['miss']; |
|
233
|
|
|
} |
|
234
|
|
|
|
|
235
|
|
|
/** |
|
236
|
|
|
* Get stats (call/miss/hit/memory). |
|
237
|
|
|
* |
|
238
|
|
|
* @since 7.5 |
|
239
|
|
|
*/ |
|
240
|
|
|
public function getStats(): array |
|
241
|
|
|
{ |
|
242
|
|
|
return $this->stats; |
|
243
|
|
|
} |
|
244
|
|
|
|
|
245
|
|
|
public function isCallsLoggingEnabled(): bool |
|
246
|
|
|
{ |
|
247
|
|
|
return $this->logCalls; |
|
248
|
|
|
} |
|
249
|
|
|
|
|
250
|
|
|
public function getCalls(): array |
|
251
|
|
|
{ |
|
252
|
|
|
return $this->calls; |
|
253
|
|
|
} |
|
254
|
|
|
|
|
255
|
|
|
public function getLoadedUnCachedHandlers(): array |
|
256
|
|
|
{ |
|
257
|
|
|
return $this->unCachedHandlers; |
|
258
|
|
|
} |
|
259
|
|
|
} |
|
260
|
|
|
|