From c57f7140deec1da80db34eecddf12257c3abbe8d Mon Sep 17 00:00:00 2001 From: David Dreschner Date: Mon, 19 Oct 2026 13:54:39 +0200 Subject: [PATCH] perf(LogIterator): Read long lines in linear time MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit LogIterator reads the log backwards in chunks of 8 KB. When a line spans several chunks, every chunk is prepended to the whole buffer before the whole buffer is searched for a newline again. Reading a line of length L therefore takes O(L²) time. Such long lines can be written, for example by occ upgrade, which forces the debug log level. A log with a few of them stalls the "Errors in the log" setup check and the log viewer. Remember where the line ends, only search the newly read chunk for its start, and then read the whole line at once. This reduces the time to O(L). Assisted-by: ClaudeCode:claude-opus-5-5 Signed-off-by: David Dreschner --- lib/Log/LogIterator.php | 21 +++++++++++++++--- tests/Unit/Log/LogIteratorTest.php | 34 ++++++++++++++++++++++++++++++ 2 files changed, 52 insertions(+), 3 deletions(-) diff --git a/lib/Log/LogIterator.php b/lib/Log/LogIterator.php index 89980d413..5d27119e6 100644 --- a/lib/Log/LogIterator.php +++ b/lib/Log/LogIterator.php @@ -76,30 +76,45 @@ private function fillBuffer(): void { } public function next(): void { + // End offset of a line spanning multiple chunks. Its chunks are dropped once searched + // and the whole line is read again at once when its start is found. + $lineEnd = null; // Loop through each character of the file looking for new lines while ($this->position >= 0) { $newlinePos = strrpos($this->buffer, "\n"); if ($newlinePos !== false) { - if ($newlinePos + 1 === strlen($this->buffer)) { + if ($lineEnd === null && $newlinePos + 1 === strlen($this->buffer)) { // try again with truncated buffer if it ends with newline, i.e. on first call $this->buffer = substr($this->buffer, 0, $newlinePos); continue; } - $this->lastLine = substr($this->buffer, $newlinePos + 1); + $this->lastLine = $lineEnd === null + ? substr($this->buffer, $newlinePos + 1) + : $this->readRange($this->position + $newlinePos + 1, $lineEnd); $this->buffer = substr($this->buffer, 0, $newlinePos); $this->currentKey++; return; } elseif ($this->position === 0) { - $this->lastLine = $this->buffer; + $this->lastLine = $lineEnd === null ? $this->buffer : $this->readRange(0, $lineEnd); $this->buffer = ''; $this->currentKey++; return; } else { + // $lineEnd must stay null until the line has content, the trailing newline check relies on it + if ($this->buffer !== '') { + $lineEnd ??= $this->position + strlen($this->buffer); + $this->buffer = ''; + } $this->fillBuffer(); } } } + private function readRange(int $start, int $end): string { + fseek($this->handle, $start); + return (string)stream_get_contents($this->handle, $end - $start); + } + public function valid(): bool { if (!is_resource($this->handle)) { return false; diff --git a/tests/Unit/Log/LogIteratorTest.php b/tests/Unit/Log/LogIteratorTest.php index 1c643d4a5..d40fb2008 100644 --- a/tests/Unit/Log/LogIteratorTest.php +++ b/tests/Unit/Log/LogIteratorTest.php @@ -23,6 +23,40 @@ private function getLogIterator(string $log) { return new LogIterator($handle, \DateTime::ATOM, 'UTC'); } + private function getLogLine(string $reqId, int $length): string { + $emptyLine = json_encode(['reqId' => $reqId, 'level' => 3, 'message' => '']); + $line = json_encode(['reqId' => $reqId, 'level' => 3, 'message' => str_repeat('a', $length - strlen($emptyLine))]); + $this->assertSame($length, strlen($line)); + return $line; + } + + public static function trailingNewlineProvider(): array { + return [ + 'without trailing newline' => [''], + 'with trailing newline' => ["\n"], + ]; + } + + /** + * @dataProvider trailingNewlineProvider + */ + public function testGetLinesSpanningMultipleChunks(string $trailingNewline): void { + // The first line starts at the beginning of the file. The last line and the trailing newline fill + // exactly two chunks, so the newline in front of the last line is the last byte of the next chunk. + $first = $this->getLogLine('1', 3 * LogIterator::CHUNK_SIZE + 17); + $middle = $this->getLogLine('2', 100); + $last = $this->getLogLine('3', 2 * LogIterator::CHUNK_SIZE - strlen($trailingNewline)); + $log = $this->getLogIterator($first . "\n" . $middle . "\n" . $last . $trailingNewline); + + $entries = iterator_to_array($log); + + $this->assertSame([ + json_decode($last, true), + json_decode($middle, true), + json_decode($first, true), + ], $entries); + } + public function testGetLines() { $log = $this->getLogIterator( '{"reqId":"1","level":3,"time":"2019-11-04T18:50:57+00:00","remoteAddr":"127.0.0.1","user":"admin","app":"comments","method":"GET","url":"/settings/admin/logging","message":{"Exception":"RuntimeException","Message":"App class OCA\\\\Comments\\\\AppInfo\\\\Application is not setup via query() but directly","Code":0,"Trace":[{"file":"/srv/http/cloud/apps/comments/lib/AppInfo/Application.php","line":42,"function":"__construct","class":"OCP\\\\AppFramework\\\\App","type":"->","args":["comments",[]]},{"file":"/srv/http/cloud/apps/comments/appinfo/app.php","line":24,"function":"__construct","class":"OCA\\\\Comments\\\\AppInfo\\\\Application","type":"->","args":[]},{"file":"/srv/http/cloud/lib/private/legacy/app.php","line":260,"args":["/srv/http/cloud/apps/comments/appinfo/app.php"],"function":"require_once"},{"file":"/srv/http/cloud/lib/private/legacy/app.php","line":154,"function":"requireAppFile","class":"OC_App","type":"::","args":["comments"]},{"file":"/srv/http/cloud/lib/private/legacy/app.php","line":127,"function":"loadApp","class":"OC_App","type":"::","args":["comments"]},{"file":"/srv/http/cloud/lib/base.php","line":991,"function":"loadApps","class":"OC_App","type":"::","args":[]},{"file":"/srv/http/cloud/index.php","line":42,"function":"handleRequest","class":"OC","type":"::","args":[]}],"File":"/srv/http/cloud/lib/public/AppFramework/App.php","Line":77,"CustomMessage":"--"},"userAgent":"Mozilla","version":"18.0.0.1"}