Re: How to log 'user time' in postgres logs - Mailing list pgsql-general

From Adrian Klaver
Subject Re: How to log 'user time' in postgres logs
Date
Msg-id c944a788-7c76-4935-0148-2209883ac962@aklaver.com
Whole thread Raw
In response to Re: How to log 'user time' in postgres logs  (francis picabia <fpicabia@gmail.com>)
List pgsql-general
On 8/28/19 11:36 AM, francis picabia wrote:
> 
> 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

Caching software in the mix?

More below.

> 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 log_duration will show that.
If you want to verify open psql and set \timing on and run your statements.


> 
> 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.
> 



-- 
Adrian Klaver
adrian.klaver@aklaver.com



pgsql-general by date:

Previous
From: Rich Shepard
Date:
Subject: Re: Query using 'LIKE' returns empty set [FIXED]
Next
From: Peter Grman
Date:
Subject: Bad Estimate for multi tenant database queries