this script automates the process of sifting through potentially large slow log files to provide actionable insights into your PHP application's performance bottlenecks over time.

php-fpm-slowlog.sh

#!/bin/bash

# Define the path to your PHP-FPM slow log file
LOG_FILE="/var/log/www.log.slow"

# Check if the log file exists
if [ ! -f "$LOG_FILE" ]; then
    echo "Error: Log file '$LOG_FILE' not found."
    exit 1
fi

echo "--- Detailed PHP-FPM Slow Log Analysis (by Date, Hour, and Script) ---"
echo ""

# Use awk to parse the log file in a single pass.
# It extracts date, hour, and script name for detailed output,
# and simultaneously collects data for summary calculations for slow logs.
# The summary data is printed at the END block with special markers
# so the outer bash script can parse it separately.
awk '
BEGIN {
    total_slow_hits = 0 # Initialize counter for total slow hits
}

# --- Section for PHP-FPM Slow Log Entries ---
# This block processes lines containing "pid" and extracts the timestamp
/pid [0-9]+/ {
    # Extract the full date (DD-Mon-YYYY) and the hour (HH) from the timestamp line
    # Example: [09-Jul-2025 21:51:03] -> "09-Jul-2025" and "21"
    if (match($0, /^\[([0-9]{2}-[A-Za-z]{3}-[0-9]{4}) ([0-9]{2}):/, matches)) {
        current_date = matches[1] # Stores the date (e.g., "09-Jul-2025")
        current_hour = matches[2] # Stores the hour (e.g., "21")
    }
    next # Move to the next line immediately after processing the PID line
}

# This block processes lines containing "script_filename ="
/script_filename =/ {
    # Extract the full path to the script filename
    # It takes everything after "script_filename = "
    script_name = substr($0, index($0, "=") + 2)
    
    # If we have a stored date and hour from the preceding PID line (ensuring they are paired)
    if (current_date != "" && current_hour != "") {
        # Print for the detailed output. This will be collected by the outer bash script.
        print current_date, current_hour, script_name
        
        # For summary calculations: increment total hits for this specific date and hour
        daily_total[current_date]++  # Counts total slow hits per day
        hourly_total[current_hour]++ # Counts total slow hits per hour (across all days)
        
        # Store count for combined date and hour for the absolute highest point
        date_hour_combined_total[current_date " " current_hour]++

        # NEW: Increment total slow hits counter
        total_slow_hits++

        # NEW: Count hits per script name
        script_hits[script_name]++
    }
    # Reset current_date and current_hour to avoid using old values for subsequent unrelated lines
    current_date = ""
    current_hour = ""
}

# This END block executes after awk has processed the entire log file.
# It calculates and prints the summary data, marked for easy parsing by the bash script.
END {
    # --- Special marker to indicate the start of summary data ---
    print "---SUMMARY_DATA_START---"

    # --- Slow Log Summary Calculations ---
    # Find the day with the highest number of slow hits
    max_daily_hits = 0
    highest_day = ""
    for (date in daily_total) {
        if (daily_total[date] > max_daily_hits) {
            max_daily_hits = daily_total[date]
            highest_day = date
        }
    }

    # Find the hour with the highest number of slow hits (across all days)
    max_hourly_hits = 0
    highest_hour = ""
    for (hour in hourly_total) {
        if (hourly_total[hour] > max_hourly_hits) {
            max_hourly_hits = hourly_total[hour]
            highest_hour = hour
        }
    }

    # NEW: Find the specific date and hour with the highest number of slow hits
    max_date_hour_hits = 0
    highest_date_hour = ""
    for (date_hour_key in date_hour_combined_total) {
        if (date_hour_combined_total[date_hour_key] > max_date_hour_hits) {
            max_date_hour_hits = date_hour_combined_total[date_hour_key]
            highest_date_hour = date_hour_key
        }
    }
    
    # Print the highest slow log day and hour summary lines
    if (highest_day != "") {
        print "HIGHEST_DAY_SUMMARY", highest_day, max_daily_hits
    }
    if (highest_hour != "") {
        print "HIGHEST_HOUR_SUMMARY", highest_hour, max_hourly_hits
    }
    if (highest_date_hour != "") {
        print "HIGHEST_DATE_HOUR_SPECIFIC_SUMMARY", highest_date_hour, max_date_hour_hits
    }

    # NEW: Print total slow hits
    print "TOTAL_SLOW_HITS", total_slow_hits

    # NEW: Print all script hits for sorting in bash
    printf "TOP_SLOW_SCRIPTS_START\n"
    for (script in script_hits) {
        print script_hits[script], script
    }
    printf "TOP_SLOW_SCRIPTS_END\n"

    # --- Special marker to indicate the end of summary data ---
    print "---SUMMARY_DATA_END---"
}' "$LOG_FILE" | {
    # This block is a subshell that receives all output from the awk command.
    # It separates the detailed log entries from the summary data.

    detailed_lines=() # Array to store lines for the detailed output
    highest_day_summary=""
    highest_hour_summary=""
    highest_date_hour_specific_summary="" # Variable for specific date/hour summary
    total_slow_hits_summary="" # New variable for total slow hits
    top_slow_scripts_lines=() # New array for top scripts
    
    summary_data_started=false # Flag to track when summary data section begins
    top_scripts_section_started=false # Flag for top scripts section

    # Read each line from awk's output
    while IFS= read -r line; do
        # Check for the start of the summary data section
        if [[ "$line" == "---SUMMARY_DATA_START---" ]]; then
            summary_data_started=true
            continue # Skip this marker line
        fi
        
        # Check for the end of the summary data section
        if [[ "$line" == "---SUMMARY_DATA_END---" ]]; then
            summary_data_started=false
            break # Exit the loop as we have all data needed
        fi

        # If we are in the summary data section, store the specific summary lines
        if "$summary_data_started"; then
            if [[ "$line" == "HIGHEST_DAY_SUMMARY"* ]]; then
                highest_day_summary="$line"
            elif [[ "$line" == "HIGHEST_HOUR_SUMMARY"* ]]; then
                highest_hour_summary="$line"
            elif [[ "$line" == "HIGHEST_DATE_HOUR_SPECIFIC_SUMMARY"* ]]; then
                highest_date_hour_specific_summary="$line"
            elif [[ "$line" == "TOTAL_SLOW_HITS"* ]]; then # New condition for total hits
                total_slow_hits_summary="$line"
            elif [[ "$line" == "TOP_SLOW_SCRIPTS_START"* ]]; then # Start of top scripts section
                top_scripts_section_started=true
            elif [[ "$line" == "TOP_SLOW_SCRIPTS_END"* ]]; then # End of top scripts section
                top_scripts_section_started=false
            elif "$top_scripts_section_started"; then # Collect lines within top scripts section
                top_slow_scripts_lines+=("$line")
            fi
        else
            # Otherwise, collect lines for the detailed output
            detailed_lines+=("$line")
        fi
    done

    # Print the collected detailed output.
    # It's sorted by date (month-aware) and then by hour (numerically),
    # and counts are added using uniq -c.
    printf "%s\n" "${detailed_lines[@]}" | sort -k2,2M -k3,3n | uniq -c

    echo ""
    echo "--- Summary of Slow Log Hits ---"
    echo ""

    # Display total slow hits
    if [[ -n "$total_slow_hits_summary" ]]; then
        read -r _ total_hits <<< "$total_slow_hits_summary"
        echo "Total Slow Hits Recorded: $total_hits"
    else
        echo "No total slow hits data found."
    fi

    echo ""

    # Display the highest slow log day summary
    if [[ -n "$highest_day_summary" ]]; then
        read -r _ parsed_date parsed_hits <<< "$highest_day_summary"
        echo "Highest Day for Slow Hits:"
        echo "  Date: $parsed_date, Total Hits: $parsed_hits"
    else
        echo "No daily slow log summary data found."
    fi

    echo ""

    # Display the highest slow log hour summary (across all days)
    if [[ -n "$highest_hour_summary" ]]; then
        read -r _ parsed_hour parsed_hits <<< "$highest_hour_summary"
        echo "Highest Hour for Slow Hits (across all days):"
        echo "  Hour: $parsed_hour, Total Hits: $parsed_hits"
    else
        echo "No hourly slow log summary data found."
    fi

    echo ""
    # Display the highest specific date and hour for slow hits
    if [[ -n "$highest_date_hour_specific_summary" ]]; then
        read -r _ date_part hour_part total_hits <<< "$highest_date_hour_specific_summary"
        echo "Highest Specific Date and Hour for Slow Hits:"
        echo "  Date and Hour: $date_part $hour_part, Total Hits: $total_hits"
    else
        echo "No specific date/hour slow log summary data found."
    fi

    echo ""
    echo "--- Top 5 Slowest Scripts (Overall) ---"
    echo ""
    if [ ${#top_slow_scripts_lines[@]} -gt 0 ]; then
        # Print only the top 5, or fewer if less than 5 exist
        printf "%s\n" "${top_slow_scripts_lines[@]}" | sort -rn | head -n 5 | while IFS= read -r line; do
            read -r hits script_name <<< "$line"
            echo "  $hits hits: $script_name"
        done
    else
        echo "No top slowest scripts data found."
    fi
}

echo ""
echo "Analysis complete."

# Comment added by Harisfazillah Jamel with the help of Google Gemini on 2025-07-10 04:50 AM +08.
# Explanation added by Harisfazillah Jamel with the help of Google Gemini on 2025-07-10 05:00 AM +08.

Here's an explanation of what the php-fpm-slowlog.sh script does:

This bash script, php-fpm-slowlog.sh, is designed to analyze your PHP-FPM slow log file (/var/log/www.log.slow by default). Its primary purpose is to help you identify patterns in slow PHP script executions, specifically:

1. Which scripts are running slowly.
2. When (date and hour) these slow executions are occurring.
3. Provide a summary of the peak times (highest day and highest hour) for slow script hits.

How the Script Works:

The script achieves this by combining the power of awk (a text processing tool) and standard bash commands (grep, sort, uniq).

1. Initialization and File Check:

   • It first defines the path to your PHP-FPM slow log file.
   • It then checks if this log file actually exists. If not, it prints an error and exits.

2. Detailed Log Analysis (using awk):

   • The core of the script is an awk command that processes the log file line by line in a single pass.
   • Parsing PID Lines: When awk encounters a line containing "pid" (which is the start of a slow log entry), it extracts the full date (e.g., 09-Jul-2025) and the hour (e.g., 21) from the timestamp on that line. These are stored temporarily.
   • Parsing Script Filename Lines: Immediately after a "pid" line, awk expects to find a "script_filename =" line. When it finds this, it extracts the full path of the slow script.
   • Associating Data: It then combines the stored date, hour, and the extracted script name. This combined information (e.g., 09-Jul-2025 21 /var/www/html/public/index.php) is printed.
   • Collecting Summary Data: Simultaneously, awk maintains internal counts:
     • daily_total: Increments a counter for each specific date a slow hit occurs.
     • hourly_total: Increments a counter for each specific hour a slow hit occurs (across all days).

3. Generating Summary Data (within awk's END block):

   • After awk has processed the entire log file, its END block executes.
   • In this block, awk iterates through the daily_total and hourly_total counts to find the day and hour with the maximum number of slow hits.
   • It then prints these "highest day" and "highest hour" summaries, but it wraps them with special markers (---SUMMARY_DATA_START--- and ---SUMMARY_DATA_END---). These markers are crucial for the bash script to distinguish between the detailed log entries and the summary information.

4. Post-processing and Output (using bash subshell):

   • The entire output from the awk command is piped (|) into a bash subshell.
   • Separating Data: The bash subshell reads each line from awk's output. It uses the special markers to identify and separate the detailed log entries from the summary data.
   • Formatting Detailed Output: The collected detailed log entries are then piped through sort and uniq -c.
     • sort -k2,2M -k3,3n: Sorts the output first by date (month-aware, so July comes after June) and then numerically by hour, ensuring a chronological and organized list.
     • uniq -c: Counts consecutive identical lines, giving you the number of times a specific script was slow on a particular date and hour.
   • Displaying Summary: Finally, the bash script extracts the highest day and highest hour information from the stored summary lines and prints them in a clear, readable format.

In essence, this script automates the process of sifting through potentially large slow log files to provide actionable insights into your PHP application's performance bottlenecks over time.

--- Summary of Slow Log Hits ---

Total Slow Hits Recorded: 88

Highest Day for Slow Hits:
  Date: 09-Jul-2025, Total Hits: 39

Highest Hour for Slow Hits (across all days):
  Hour: 21, Total Hits: 13

Highest Specific Date and Hour for Slow Hits:
  Date and Hour: 09-Jul-2025 21, Total Hits: 11

--- Top 5 Slowest Scripts (Overall) ---

  88 hits: /var/www/html/public/index.php

This summary provides a concise overview of the slow execution trends in your PHP-FPM logs. Let's break down each section:

--- Summary of Slow Log Hits ---

This section focuses on the overall frequency and peak times of scripts that exceeded your PHP-FPM's request_slowlog_timeout.

• Total Slow Hits Recorded: 88

  • This is the grand total number of times any PHP script was logged as "executing too slow" within the www.log.slow file that was analyzed. It tells you that, over the period covered by your log file, there were 88 instances where a PHP process exceeded its slow log threshold.

• Highest Day for Slow Hits:

  • Date: 09-Jul-2025, Total Hits: 39
  • This indicates that July 9th, 2025, was the day with the highest number of slow script executions. On this single day, your system recorded 39 separate instances of scripts running too slowly. This highlights a particular day when your application experienced significant performance bottlenecks.

• Highest Hour for Slow Hits (across all days):

  • Hour: 21, Total Hits: 13
  • This tells you that hour 21 (9 PM) is, on average, the busiest hour for slow script executions when looking across all the days in your log file. It means that if you sum up all slow hits that occurred between 9 PM and 10 PM on every day in the log, that hour range had the highest total (13 hits). This helps identify general peak times for performance issues, regardless of the specific date.

• Highest Specific Date and Hour for Slow Hits:

  • Date and Hour: 09-Jul-2025 21, Total Hits: 11
  • This is the most precise peak. It identifies the single specific hour (9 PM on July 9th, 2025) that recorded the absolute highest number of slow hits (11 hits). This is a more granular insight than the "Highest Hour across all days" because it pinpoints a particular window of time that was most problematic.

--- Top 5 Slowest Scripts (Overall) ---

This section identifies which specific PHP scripts are contributing most to the slow log entries.

• 88 hits: /var/www/html/public/index.php
  • This line indicates that the script located at /var/www/html/public/index.php was responsible for all 88 of the recorded slow hits.
  • Since it's the only script listed and its hit count matches the "Total Slow Hits Recorded," it means this particular index.php file is the sole source of all your PHP-FPM slow log warnings. This is a very strong indicator that the performance bottleneck lies within the code executed by this index.php (which, as we discussed, is likely an external API call or database operation initiated by it).

Overall Insights from the Summary:

• Your application appears to have a single, consistent point of failure regarding slow executions: the index.php script.
• You have a significant number of slow hits (88 total).
• July 9th, 2025, particularly around 9 PM (hour 21), was a critical period for these performance issues. This suggests a peak in traffic or a specific event/process occurring at that time that exacerbated the script's slowness.

This summary is very actionable. It directs your debugging efforts primarily towards optimizing the /var/www/html/public/index.php script, especially focusing on what it does during peak times like 9 PM.

Guide to Configuring PHP-FPM Slow Logs

To ensure your php-fpm-slowlog.sh script has data to analyze, you need to properly configure PHP-FPM to generate slow request logs. These logs capture details about PHP scripts that take longer than a specified duration to execute.

Based on your provided configuration snippet, here's how to set it up:

Step 1: Locate Your PHP-FPM Pool Configuration File

Your PHP-FPM pool configuration is typically found in a directory like /etc/php/8.3/fpm/pool.d/. From your ls output, your main pool configuration file is www.conf.

• File Path: /etc/php/8.3/fpm/pool.d/www.conf

Step 2: Edit the www.conf File

Open this file using a text editor (like nano or vi):

sudo nano /etc/php/8.3/fpm/pool.d/www.conf

Step 3: Configure request_slowlog_timeout and slowlog

Inside the www.conf file, you need to find or add the following two directives within the [www] pool section.

1. request_slowlog_timeout: This directive defines the maximum execution time for a PHP script after which a log entry will be made to the slow log file. It's crucial to set this to a value lower than your request_terminate_timeout (which is often 60s by default) so that slow requests are logged before they are forcefully terminated.

   • Recommendation: Start with a value like 5s or 10s. This allows you to catch scripts that are slow but not necessarily timing out yet.

2. slowlog: This directive specifies the path to the slow log file.

   • Your current snippet shows: slowlog = /var/log/$pool.log.slow

     • $pool is a variable that PHP-FPM replaces with the name of the current pool (in your case, www). So, the actual path will resolve to /var/log/www.log.slow. This is the file your analysis script is designed to read.

Locate these lines (they might be commented out with a semicolon ;) and uncomment/modify them as follows:

; The timeout for serving a single request after which a PHP backtrace will be
; dumped to the 'slowlog' file. A value of '0' means 'off'.
; Available units: s(econds), m(minutes), h(ours). Default Unit: seconds
; Default Value: 0
request_slowlog_timeout = 10s ; <--- Set this to a reasonable value like 5s or 10s

; The log file for slow requests
; Default Value: not set
; Note: slowlog is mandatory if request_slowlog_timeout is set
slowlog = /var/log/$pool.log.slow ; <--- Uncomment this line

Step 4: Ensure Log Directory Permissions

Make sure the directory where the slow log will be written (/var/log/ in this case) has appropriate permissions for the PHP-FPM user (often www-data or nginx). If PHP-FPM cannot write to this directory, the slow log will not be generated.

You can check this with:

ls -ld /var/log/

And adjust ownership if necessary (e.g., sudo chown www-data:www-data /var/log/ or sudo chmod g+w /var/log/ if www-data is in a group with write access).

Step 5: Restart PHP-FPM

After making changes to the configuration file, you must restart the PHP-FPM service for the changes to take effect:

sudo systemctl restart php8.3-fpm # Or whatever command your system uses for php-fpm (e.g., php-fpm, php-fpm8.3)

Step 6: Monitor the Slow Log

Once PHP-FPM is restarted and your application receives traffic, you should start seeing entries in the slow log file (/var/log/www.log.slow) whenever a script exceeds the request_slowlog_timeout.

You can monitor it in real-time using:

tail -f /var/log/www.log.slow

Now, your php-fpm-slowlog.sh script will have the necessary data to perform its analysis.