The server was running Moodle. The slow load time was noticed when loading a quiz containing multiple images. All Apache log results showed a 6 seconds or a multiple of 6 for how long it took to retrieve each image.
Interestingly, if I did a wget, on the server, to the image link (which was processed through a pluginfile.php URL) even the HTML page returned of "please login first" took consistently 6 seconds. Never 2, 3, 4, 5 or 7, 8, 9... So whatever was wrong, there was a 6 second penalty for this. We found the problem outside of the quizzes as well, so it wasn't a single part of the PHP code. In addition, our development server with a clone of data, database, apps, etc., was fast at doing any of the tests. Of course a database brought in with a dump will not include any of the cruft DB structures, so the dev server was free of the problem (and it had fewer cores, memory, etc). I was not suspecting PostgreSQL as the culprit, because all query times in the log showed roughly 1 ms response. I could tail -f the log file while loading a quiz to watch the times reported. Last night the vacuum was run (on a database of about 40GB if dumped), and since then the quizzes and everything run as fast as would be expected. It had run for about 1.5 months without vacuum. Apache, PHP and Postgres all on the same server. Memory and CPUs not taxed, load kept level while the problem quizzes were being tested. Given this experience, I'd like something that reflected the true times Postgres was spending on any work it was doing. The other possibility was it just didn't log the slower times, but I have seen larger numbers in the 10,000 ms range in the night when some backups and housekeeping happens. All log related settings: checkpoint_segments = 12 logging_collector = on log_destination = 'stderr' log_directory = 'pg_log' log_filename = 'postgresql-%a.log' log_truncate_on_rotation = on log_rotation_age = 1440 log_rotation_size = 0 log_min_messages = info log_min_error_statement = debug1 log_duration = on log_line_prefix = '<%t>' I know it does sound strange, but this is what we battled with for 2.5 days until the light came on that the vacuum had been set to off on the target system during server migration. On Wed, Aug 28, 2019 at 11:07 AM Adrian Klaver <adrian.kla...@aklaver.com> wrote: > On 8/28/19 5:36 AM, francis picabia wrote: > > > > Recently had a problem where autovacuum was accidentally left off > > and the database took 6 seconds for every task from PHP. > > I had no clue the database was the issue because I > > had the minimal > > > > log_duration = on > > log_line_prefix = '<%t>' > > > > With those settings all queries seen were roughly 1ms > > > > I need this log to show the true time it takes to get a result back. > > > > In the Linux world we have the time command which shows the user > > time reflecting all overhead added up. I'd like postgres to show > > times like that and then if there are problems I can look further, > > change logging details, etc.. > > > > I checked docs, googled, and didn't see anything obvious. > > I'm having a hard time believing autovacuum was involved in this, given > you say the queries took only 1ms on average. That would have been the > part that would have been impacted by bloated tables/out-of-date > statistics. > > Some questions: > > 1) How did you arrive at the 6 second figure? > > 2) Is the PHP application on the same server as the database? > > > > > > > > -- > Adrian Klaver > adrian.kla...@aklaver.com >
