When a request is logged in Apache’s common or combined format, it doesn’t actually show you how much time each request took to complete. To make reading logs a bit more confusing, each request is logged only once it’s completed. So a long-running request may have an earlier start time but appear later in the log than quicker requests.<\/p>\n
To help look at some timing info without going deep enough to need a debugger, I decided that step one was to use a custom log format that saved the total request time. After adding I’m using the “%D” format for compatibility with older Apache releases, which reports the response time in microseconds. I would prefer milliseconds, but when I tried using “%{ms}T” on a server running 2.4.7, it didn’t work; too old. This output is a bit hard to read when looking at the numbers, so we can try to add in a little visual aid with commas as the thousands separator.<\/p>\n Note that because we are measuring the total request time, some of the numbers may be high due to remote network latency or a slow client. I recommend correlating several samples before blaming some piece of local application code.<\/p>\n Hope this helps finding your long-running requests!<\/p>\n","protected":false},"excerpt":{"rendered":" When a request is logged in Apache’s common or combined format, it doesn’t actually show you how much time each request took to complete. To make reading logs a bit more confusing, each request is logged only once it’s completed. So a long-running request may have an earlier start time but appear later in the […]<\/p>\n","protected":false},"author":3,"featured_media":905,"comment_status":"closed","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":[],"categories":[6],"tags":[34,41,25,26],"_links":{"self":[{"href":"https:\/\/www.devolve.local\/wp-json\/wp\/v2\/posts\/902"}],"collection":[{"href":"https:\/\/www.devolve.local\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.devolve.local\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.devolve.local\/wp-json\/wp\/v2\/users\/3"}],"replies":[{"embeddable":true,"href":"https:\/\/www.devolve.local\/wp-json\/wp\/v2\/comments?post=902"}],"version-history":[{"count":2,"href":"https:\/\/www.devolve.local\/wp-json\/wp\/v2\/posts\/902\/revisions"}],"predecessor-version":[{"id":904,"href":"https:\/\/www.devolve.local\/wp-json\/wp\/v2\/posts\/902\/revisions\/904"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/www.devolve.local\/wp-json\/wp\/v2\/media\/905"}],"wp:attachment":[{"href":"https:\/\/www.devolve.local\/wp-json\/wp\/v2\/media?parent=902"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.devolve.local\/wp-json\/wp\/v2\/categories?post=902"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.devolve.local\/wp-json\/wp\/v2\/tags?post=902"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}usec:%D<\/code> to the end of my Apache custom log format, we can now see how long various requests are taking to complete.<\/p>\ntail -q -1000 *access.log | mawk 'FS=\"(:|GET |POST | HTTP\/1.1|\\\")\" {print $NF\" \"$6}' | sort -nr | head -100 > \/tmp\/heavy2<\/code><\/p>\ncat \/tmp\/heavy2 | xargs -L 1 printf \"%'d %s\\n\" | less<\/code><\/p>\n