📁 Volume II: Laravel Performance Tuning Kit

📝 Topic 25: Logging I/O Trap

Every Log::info() opens a file. 10,000 logs = 10,000 I/O operations.

"You add logging to debug your code.
You log every step of the process.
Your code runs fine in development.
In production, 10,000 logs per minute kill your disk I/O.
Your server slows to a crawl. And you have no idea why.
The culprit? Logging."

⚠️ THE HIDDEN I/O KILLER

Every call to Log::info(), Log::error(), or any logging method triggers a file write operation. For the 'daily' and 'single' log drivers, this means opening, writing, and closing a file. In a loop with 10,000 iterations, that's 10,000 file I/O operations. Your disk bandwidth is exhausted. Your application slows down. Your users suffer.

🔴 The Problem: Every Log Entry = One I/O Operation

WHAT HAPPENS WHEN YOU CALL Log::info() ═══════════════════════════════════════════════════════════════════ Log::info("Processing user {$user->id}"); │ ▼ ┌─────────────────────────────────────────────────────────────────┐ │ 1. fopen(storage/logs/laravel.log, 'a') ← Open file │ │ 2. flock() (file lock) ← Wait for lock │ │ 3. fwrite( formatted log line ) ← Write to disk │ │ 4. fflush() ← Flush buffer │ │ 5. flock() unlock ← Release lock │ │ 6. fclose() ← Close file │ └─────────────────────────────────────────────────────────────────┘ Each operation: ~0.1-1ms of I/O time FOR 10,000 LOGS (BATCH PROCESSING): ═══════════════════════════════════════════════════════════════════ Without optimization: ┌─────────────────────────────────────────────────────────────────┐ │ for ($i = 0; $i < 10000; $i++) { │ │ Log::info("Processing record {$i}"); // 10,000 I/O ops │ │ } │ │ │ │ Time: 1-10 seconds (100% I/O bound) │ └─────────────────────────────────────────────────────────────────┘ With batching: ┌─────────────────────────────────────────────────────────────────┐ │ $logs = []; │ │ for ($i = 0; $i < 10000; $i++) { │ │ $logs[] = "Processing record {$i}"; │ │ } │ │ Log::info(implode("\n", $logs)); // 1 I/O operation │ │ │ │ Time: 0.01 seconds (1 I/O operation) │ └─────────────────────────────────────────────────────────────────┘ Result: 1,000x faster!

THE LOGGING SINS

Logging inside loops — The #1 performance killer
Debug logging in production — Log::debug() on every request
Logging every database query — DB::listen() with logs
Logging every API call — Request/response dumps
Logging user activity at high volume — Every click, every view

📊 The Real Cost of Logging I/O

Number of Logs	Without Batching	With Batching	Improvement
100 logs	~10-20ms	~0.5ms	20-40x faster
1,000 logs	~100-200ms	~1ms	100-200x faster
10,000 logs	~1-2 seconds	~5-10ms	100-200x faster
100,000 logs	~10-20 seconds	~50-100ms	100-200x faster

REAL-WORLD EXAMPLE

A batch job processing 50,000 records:

Without batching: 50,000 log writes → 5-10 seconds of I/O
With batching: 1 log write → 0.005 seconds of I/O
1,000x faster batch processing

✅ The Solution: Batch Your Logs

THE GOLDEN RULE OF LOGGING

Never call Log::*() inside a loop. Collect logs in an array and write them once.

👎 BAD (10,000 I/O operations)

// Process 10,000 users
foreach ($users as $user) {
    try {
        $user->process();
        Log::info("User {$user->id} processed successfully");
    } catch (\Exception $e) {
        Log::error("User {$user->id} failed: " . $e->getMessage());
    }
}
// 10,000 logs = 10,000 I/O operations
// Time: 1-2 seconds just for logging

👍 GOOD (1 I/O operation)

$infoLogs = [];
$errorLogs = [];

foreach ($users as $user) {
    try {
        $user->process();
        $infoLogs[] = "User {$user->id} processed successfully";
    } catch (\Exception $e) {
        $errorLogs[] = "User {$user->id} failed: " . $e->getMessage();
    }
}

if ($infoLogs) {
    Log::info(implode("\n", $infoLogs));  // One write
}
if ($errorLogs) {
    Log::error(implode("\n", $errorLogs));  // One write
}
// 2 I/O operations total
// Time: 0.002 seconds

⚙️ Log Drivers and Their I/O Characteristics

Driver	I/O per Log	Notes
`single` (default)	Open, write, close (3-5 I/O calls)	Worst for high-volume logging
`daily`	Open, write, close + date check	Better than single, still bad for loops
`stack`	Multiple drivers = multiple I/O	Even worse for performance
`syslog`	Pass through to syslog daemon	Better, but still overhead
`errorlog`	PHP error log (usually less I/O)	Good for simple logging
`redis` (custom)	Network I/O to Redis	Fast, but requires Redis

BEST PRACTICE

For high-volume applications, use redis or syslog drivers, or batch your logs. Never use single or daily for high-frequency logging.

📤 Logging in Queues (The Hidden Trap)

QUEUE WORKER LOGGING

Queue workers can process thousands of jobs per minute. Each job that logs = I/O operations. If 100 jobs log 100 times each = 10,000 log writes.

SOLUTION: Batch logs in queue jobs

class ProcessUserJob implements ShouldQueue
{
    private static array $batchLogs = [];
    
    public function handle(): void
    {
        try {
            $this->user->process();
            self::$batchLogs[] = "User {$this->user->id} processed";
        } catch (\Exception $e) {
            self::$batchLogs[] = "User {$this->user->id} failed: {$e->getMessage()}";
        }
    }
    
    public function __destruct()
    {
        // Write all logs when the job finishes (or batch across jobs)
        if (!empty(self::$batchLogs)) {
            Log::info(implode("\n", self::$batchLogs));
            self::$batchLogs = [];
        }
    }
}

🔧 Contextual Logging (Laravel 8+)

LOG WITH CONTEXT (No Performance Gain, but Better Organization)

// Laravel 8+ allows adding context to logs
Log::withContext(['user_id' => $userId, 'batch' => $batchId]);

// Now every log in this request/queue job includes this context
Log::info("Processing started");  // Includes user_id and batch
Log::info("Processing completed"); // Includes user_id and batch

// Still batching needed! This doesn't reduce I/O, just adds metadata

🎯 Log Levels: What to Log in Production

表 Level Use in Production? When to Use emergency ✅ Yes System is unusable alert ✅ Yes Action must be taken immediately critical ✅ Yes Critical conditions error ✅ Yes Runtime errors warning ✅ Yes Exceptional occurrences notice ⚠️ Limited Normal but significant events info ❌ Avoid in high volume Interesting events (batch or remove) debug ❌ NO Development only

PRODUCTION LOG LEVEL

# .env - Production
LOG_LEVEL=error  # Only log errors and above

# .env - Development
LOG_LEVEL=debug  # Log everything

# In config/logging.php
'level' => env('LOG_LEVEL', 'error'),

🚀 Alternatives to File Logging for High Volume

🟢 Redis/Memory Logging

// Custom Redis logger
class RedisLogger
{
    public function log($level, $message)
    {
        Redis::lpush('logs', json_encode([
            'level' => $level,
            'message' => $message,
            'time' => microtime(true),
        ]));
    }
}

// Consumer process writes to file in batches
// Write once per second instead of per log

🔵 Database Logging (with buffer)

// Batch insert logs to database
class DbLogger
{
    private static array $buffer = [];
    
    public function log($level, $message)
    {
        self::$buffer[] = compact('level', 'message');
        
        if (count(self::$buffer) >= 100) {
            DB::table('logs')->insert(self::$buffer);
            self::$buffer = [];
        }
    }
}

📝 Topic 25 Summary: Logging I/O Trap

Pattern	I/O Operations	Time for 10k Logs	Recommendation
Log inside loop	10,000	1-2 seconds	❌ NEVER
Batch logs in array	1-2	0.001-0.002 seconds	✅ For loops
Log::info() in production	Per request	Variable	⚠️ Limit usage
Redis logging + consumer	Minimal	Very fast	✅ For high volume

📌 THE RULE: Never call Log::*() inside a loop. Collect logs in arrays and write them once. Set LOG_LEVEL=error in production to avoid debug/info logs. For high-volume logging, use Redis or database with batching.

NEXT TOPIC PREVIEW

Topic 26: Blade View Cache — Every Blade template is compiled to PHP. Without caching, this happens on every request. How view:cache saves 10-30ms per request.