search

yokawasa / mod_log_slow

Apache module for logging of slow requests handling
http://code.google.com/p/modlogslow/
Apache License 2.0
16 stars 2 forks source link

Unable to log slow queries when LogSlowBufferedLogs is "On" and outbuf is <512 #2

Open cyril-bouthors opened 10 years ago

cyril-bouthors commented 10 years ago

Hi,

After quite a lot of test cases, we came to the conclusion that mod_log_slow is unable to log queries under the following conditions:

To reproduce the issue.

for a in $(seq 0 10 500)
do
  url="http://wheezy/?$a-$(for b in $(seq $a); do echo -n x; done)"
  wget -nv -O/dev/null $url
done

Expected behavior: see all queries in the log file.

Found behavior: only lines longer than 512 are shown:

# head /var/log/apache2/mod_slow.log
5d35:53997a38:0 [12/Jun/2014:12:00:24 +0200] elapsed: 0.00 cpu: 0.00(usr)/0.00(sys) pid: 23861 ip: 10.10.0.254 host: wheezy:80 reqinfo: GET /?360-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx HTTP/1.1
5d36:53997a38:0 [12/Jun/2014:12:00:24 +0200] elapsed: 0.00 cpu: 0.00(usr)/0.00(sys) pid: 23862 ip: 10.10.0.254 host: wheezy:80 reqinfo: GET /?370-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx HTTP/1.1
5d37:53997a38:0 [12/Jun/2014:12:00:24 +0200] elapsed: 0.00 cpu: 0.00(usr)/0.00(sys) pid: 23863 ip: 10.10.0.254 host: wheezy:80 reqinfo: GET /?380-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx HTTP/1.1

Here is the configuration used:

    LogSlowEnabled On
    LogSlowFileName /var/log/apache2/mod_slow.log
    LogSlowBufferedLogs On
    LogSlowLongRequestTime 0

This bug is not reproducible if LogSlowBufferedLogs is disable or if we are running Debian/sid + Apache 2.4.

In mod_log_slow.c, I've found this:

#define LOGBUF_SIZE                (512)

It's maybe related, See https://github.com/yokawasa/mod_log_slow/blob/master/mod_log_slow.c#L40

Do you think there could be a way to fix this issue with short outbuf?

Regards,

yokawasa commented 10 years ago

Hi Cyril,

Thank you for reporting this. Also my apologies for not responding earlier.

First, let me explain an expected behavior of buffering log function below:

When LogSlowBufferedLogs is enabled, slow log lines are temporary stored in memory buffer (size is 512 byte), and they are flushed on to slow log file when the total size of slow logs get more than 512. In other words, slow log lines are not flushed on to the log file until the total size of accumulated slow log lines in the buffer get more than 512. If single log line is more than 512, it is flushed on to the log file without being stored in temporary buffer. In addition, slow log stored in the buffer are flushed on the low in stopping Apache.

So, you may observe that even lines shorter than 512 are shown when the total size of accumulated log sizes get more than 512.

Please let me know if you have problem or concern on this issue. Any input is appreciated.

cyril-bouthors commented 10 years ago

According to my tests, absolutely no line is logged even after several thousands accesses.

yokawasa commented 10 years ago

Thanks for your feedback. Let me provide current update. Unfortunately I haven't make it reproducing the issue. I've run your script under the following conditions but I see lines shorter than 512 are logged.

Can you please provide the output of "httpd -V" command run on your environment for my further investigation on this issue?

The output of "httpd -V" on my environment is .. $ apache/bin/httpd -V

Server version: Apache/2.2.22 (Unix)
Server built:   Jun 29 2014 23:23:07
Server's Module Magic Number: 20051115:30
Server loaded:  APR 1.4.5, APR-Util 1.4.1
Compiled using: APR 1.4.5, APR-Util 1.4.1
Architecture:   64-bit
Server MPM:     Prefork
  threaded:     no
    forked:     yes (variable process count)
cyril-bouthors commented 10 years ago

On Mon, Jun 30, 2014 at 5:32 PM, Yoichi Kawasaki notifications@github.com wrote:

Can you please provide the output of "httpd -V" command run on your environment for my further investigation on this issue?

"httpd" is called "apache2" under Debian:

apache2 -V

Server version: Apache/2.2.22 (Debian) Server built: Feb 1 2014 21:26:10 Server's Module Magic Number: 20051115:30 Server loaded: APR 1.4.6, APR-Util 1.4.1 Compiled using: APR 1.4.6, APR-Util 1.4.1 Architecture: 64-bit Server MPM: ITK threaded: no forked: yes (variable process count) Server compiled with.... -D APACHE_MPM_DIR="server/mpm/experimental/itk" -D APR_HAS_SENDFILE -D APR_HAS_MMAP -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled) -D APR_USE_SYSVSEM_SERIALIZE -D APR_USE_PTHREAD_SERIALIZE -D APR_HAS_OTHER_CHILD -D AP_HAVE_RELIABLE_PIPED_LOGS -D DYNAMIC_MODULE_LIMIT=128 -D HTTPD_ROOT="/etc/apache2" -D SUEXEC_BIN="/usr/lib/apache2/suexec" -D DEFAULT_PIDLOG="/var/run/apache2.pid" -D DEFAULT_SCOREBOARD="logs/apache_runtime_status" -D DEFAULT_LOCKFILE="/var/run/apache2/accept.lock" -D DEFAULT_ERRORLOG="logs/error_log" -D AP_TYPES_CONFIG_FILE="mime.types"

-D SERVER_CONFIG_FILE="apache2.conf"

Cyril Bouthors - ISVTEC https://www.isvtec.com/: Web Platform Managed Services and Scalability 14 avenue de l'Opéra, 75001 Paris. 201 rue Vendôme, 69003 Lyon ☎ 01 84 16 16 17 - Ligne directe : 0x7B9EE3B0E - Fax : 01 77 72 57 24