Re: How to log 'user time' in postgres logs

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(dot)klaver(at)aklaver(dot)com