[ADMIN] What is syslog:duration reporting ... ?
'k, I've been wracking my brains over this today, and I'm either mis-understanding what is being reported *or* its reporting wrong ... According to syslog: LOG: duration: 4107.987 ms statement: UPDATE session SET hit_time=now() WHERE md5='8b8e7b7ff9b1b2ed5fc60218ced28d00'; But, if I do an EXPLAIN ANALYZE: # explain analyze UPDATE session SET hit_time=now() WHERE md5='702c6cb20d5eb254c3feb2991e7e5e31'; QUERY PLAN Index Scan using session_md5_key on "session" (cost=0.00..6.01 rows=1 width=93) (actual time=0.060..0.060 rows=0 loops=1) Index Cond: (md5 = '702c6cb20d5eb254c3feb2991e7e5e31'::bpchar) Total runtime: 0.171 ms (3 rows) And it doesn't matter what value I put for md5, I still get <1ms ... I could see some variations, but almost 4000x slower to *really* run the query vs an explain analyze? This is with 7.4.2 ... Marc G. Fournier Hub.Org Networking Services (http://www.hub.org) Email: [EMAIL PROTECTED] Yahoo!: yscrappy ICQ: 7615664 ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster
Re: [ADMIN] What is syslog:duration reporting ... ?
As I know EXPLAIN ANALYZE runs the query. I think you are just running the query two times. The first time you run the query it will take a long time to be processed - after the first run the query planner will remember the best way to run the query so your second run runs much faster. I can reproduce this behavior for some queries under 8.0.1 - so I'm not 100% sure if it is the same behavior under 7.4.2. I'm still wondering why you first query takes about 4107.987 ms - this kind of query has usually have to run much much faster. When did you vacuumed the table the last time? Marc G. Fournier wrote: 'k, I've been wracking my brains over this today, and I'm either mis-understanding what is being reported *or* its reporting wrong ... According to syslog: LOG: duration: 4107.987 ms statement: UPDATE session SET hit_time=now() WHERE md5='8b8e7b7ff9b1b2ed5fc60218ced28d00'; But, if I do an EXPLAIN ANALYZE: # explain analyze UPDATE session SET hit_time=now() WHERE md5='702c6cb20d5eb254c3feb2991e7e5e31'; QUERY PLAN Index Scan using session_md5_key on "session" (cost=0.00..6.01 rows=1 width=93) (actual time=0.060..0.060 rows=0 loops=1) Index Cond: (md5 = '702c6cb20d5eb254c3feb2991e7e5e31'::bpchar) Total runtime: 0.171 ms (3 rows) And it doesn't matter what value I put for md5, I still get <1ms ... I could see some variations, but almost 4000x slower to *really* run the query vs an explain analyze? This is with 7.4.2 ... Marc G. Fournier Hub.Org Networking Services (http://www.hub.org) Email: [EMAIL PROTECTED] Yahoo!: yscrappy ICQ: 7615664 ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster ---(end of broadcast)--- TIP 6: explain analyze is your friend
Re: [ADMIN] What is syslog:duration reporting ... ?
On Thu, 25 Aug 2005, Aldor wrote: As I know EXPLAIN ANALYZE runs the query. I think you are just running the query two times. The first time you run the query it will take a long time to be processed - after the first run the query planner will remember the best way to run the query so your second run runs much faster. I can reproduce this behavior for some queries under 8.0.1 - so I'm not 100% sure if it is the same behavior under 7.4.2. I'm still wondering why you first query takes about 4107.987 ms - this kind of query has usually have to run much much faster. That would work if I were to get really occasional high values in syslog, but this is almost a consist thing over a very short period of time: Aug 25 14:53:32 forgehouse-s1 postgres[23721]: [2-1] LOG: duration: 567.559 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; Aug 25 14:53:32 forgehouse-s1 postgres[23722]: [2-1] LOG: duration: 565.966 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:33 forgehouse-s1 postgres[23723]: [2-1] LOG: duration: 1192.789 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:53 forgehouse-s1 postgres[23727]: [2-1] LOG: duration: 12159.162 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:54 forgehouse-s1 postgres[23728]: [2-1] LOG: duration: 3283.185 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; Aug 25 14:53:57 forgehouse-s1 postgres[23729]: [2-1] LOG: duration: 2116.516 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; And you will notice that the last two are the exact same md5 value ... When did you vacuumed the table the last time? pg_autovacuum is running to keep things up to date, and I just ran a VACUUM FULL *and* a REINDEX, just to make sure things are clean ... No matter when I try it, I can't seem to get a value above 10ms for that query above when I do it from psql ... Marc G. Fournier wrote: 'k, I've been wracking my brains over this today, and I'm either mis-understanding what is being reported *or* its reporting wrong ... According to syslog: LOG: duration: 4107.987 ms statement: UPDATE session SET hit_time=now() WHERE md5='8b8e7b7ff9b1b2ed5fc60218ced28d00'; But, if I do an EXPLAIN ANALYZE: # explain analyze UPDATE session SET hit_time=now() WHERE md5='702c6cb20d5eb254c3feb2991e7e5e31'; QUERY PLAN Index Scan using session_md5_key on "session" (cost=0.00..6.01 rows=1 width=93) (actual time=0.060..0.060 rows=0 loops=1) Index Cond: (md5 = '702c6cb20d5eb254c3feb2991e7e5e31'::bpchar) Total runtime: 0.171 ms (3 rows) And it doesn't matter what value I put for md5, I still get <1ms ... I could see some variations, but almost 4000x slower to *really* run the query vs an explain analyze? This is with 7.4.2 ... Marc G. Fournier Hub.Org Networking Services (http://www.hub.org) Email: [EMAIL PROTECTED] Yahoo!: yscrappy ICQ: 7615664 ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster Marc G. Fournier Hub.Org Networking Services (http://www.hub.org) Email: [EMAIL PROTECTED] Yahoo!: yscrappy ICQ: 7615664 ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [ADMIN] What is syslog:duration reporting ... ?
Can you post the code you created the INDEX with - I think there is something which could explain the duration. Marc G. Fournier wrote: On Thu, 25 Aug 2005, Aldor wrote: As I know EXPLAIN ANALYZE runs the query. I think you are just running the query two times. The first time you run the query it will take a long time to be processed - after the first run the query planner will remember the best way to run the query so your second run runs much faster. I can reproduce this behavior for some queries under 8.0.1 - so I'm not 100% sure if it is the same behavior under 7.4.2. I'm still wondering why you first query takes about 4107.987 ms - this kind of query has usually have to run much much faster. That would work if I were to get really occasional high values in syslog, but this is almost a consist thing over a very short period of time: Aug 25 14:53:32 forgehouse-s1 postgres[23721]: [2-1] LOG: duration: 567.559 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; Aug 25 14:53:32 forgehouse-s1 postgres[23722]: [2-1] LOG: duration: 565.966 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:33 forgehouse-s1 postgres[23723]: [2-1] LOG: duration: 1192.789 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:53 forgehouse-s1 postgres[23727]: [2-1] LOG: duration: 12159.162 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:54 forgehouse-s1 postgres[23728]: [2-1] LOG: duration: 3283.185 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; Aug 25 14:53:57 forgehouse-s1 postgres[23729]: [2-1] LOG: duration: 2116.516 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; And you will notice that the last two are the exact same md5 value ... When did you vacuumed the table the last time? pg_autovacuum is running to keep things up to date, and I just ran a VACUUM FULL *and* a REINDEX, just to make sure things are clean ... No matter when I try it, I can't seem to get a value above 10ms for that query above when I do it from psql ... Marc G. Fournier wrote: 'k, I've been wracking my brains over this today, and I'm either mis-understanding what is being reported *or* its reporting wrong ... According to syslog: LOG: duration: 4107.987 ms statement: UPDATE session SET hit_time=now() WHERE md5='8b8e7b7ff9b1b2ed5fc60218ced28d00'; But, if I do an EXPLAIN ANALYZE: # explain analyze UPDATE session SET hit_time=now() WHERE md5='702c6cb20d5eb254c3feb2991e7e5e31'; QUERY PLAN Index Scan using session_md5_key on "session" (cost=0.00..6.01 rows=1 width=93) (actual time=0.060..0.060 rows=0 loops=1) Index Cond: (md5 = '702c6cb20d5eb254c3feb2991e7e5e31'::bpchar) Total runtime: 0.171 ms (3 rows) And it doesn't matter what value I put for md5, I still get <1ms ... I could see some variations, but almost 4000x slower to *really* run the query vs an explain analyze? This is with 7.4.2 ... Marc G. Fournier Hub.Org Networking Services (http://www.hub.org) Email: [EMAIL PROTECTED] Yahoo!: yscrappy ICQ: 7615664 ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster Marc G. Fournier Hub.Org Networking Services (http://www.hub.org) Email: [EMAIL PROTECTED] Yahoo!: yscrappy ICQ: 7615664 ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [ADMIN] What is syslog:duration reporting ... ?
On Thu, Aug 25, 2005 at 03:56:36PM -0300, Marc G. Fournier wrote: > On Thu, 25 Aug 2005, Aldor wrote: > >I'm still wondering why you first query takes about 4107.987 ms - this > >kind of query has usually have to run much much faster. > > That would work if I were to get really occasional high values in syslog, > but this is almost a consist thing over a very short period of time: Are the updates happening inside a transaction? Is it possible that they're being blocked by other transactions that update the same record around the same time and don't commit immediately? I can duplicate the results you're seeing by doing that. -- Michael Fuhr ---(end of broadcast)--- TIP 4: Have you searched our list archives? http://archives.postgresql.org
Re: [ADMIN] What is syslog:duration reporting ... ?
On Thu, Aug 25, 2005 at 01:55:08PM -0600, Michael Fuhr wrote: > Are the updates happening inside a transaction? Is it possible > that they're being blocked by other transactions that update the > same record around the same time and don't commit immediately? > I can duplicate the results you're seeing by doing that. As for why you don't see long durations with EXPLAIN ANALYZE, here's a possible explanation: "ordinary" updates of the same record might happen close together because that's how the application works, but by the time you run EXPLAIN ANALYZE no other transactions are updating that record so the update executes immediately. -- Michael Fuhr ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [ADMIN] What is syslog:duration reporting ... ?
Aug 25 14:53:32 forgehouse-s1 postgres[23721]: [2-1] LOG: duration: 567.559 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; Aug 25 14:53:32 forgehouse-s1 postgres[23722]: [2-1] LOG: duration: 565.966 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:33 forgehouse-s1 postgres[23723]: [2-1] LOG: duration: 1192.789 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:53 forgehouse-s1 postgres[23727]: [2-1] LOG: duration: 12159.162 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:54 forgehouse-s1 postgres[23728]: [2-1] LOG: duration: 3283.185 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; Aug 25 14:53:57 forgehouse-s1 postgres[23729]: [2-1] LOG: duration: 2116.516 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; Take a look to the timestamps... they are not really close to each other... Michael Fuhr wrote: On Thu, Aug 25, 2005 at 01:55:08PM -0600, Michael Fuhr wrote: Are the updates happening inside a transaction? Is it possible that they're being blocked by other transactions that update the same record around the same time and don't commit immediately? I can duplicate the results you're seeing by doing that. As for why you don't see long durations with EXPLAIN ANALYZE, here's a possible explanation: "ordinary" updates of the same record might happen close together because that's how the application works, but by the time you run EXPLAIN ANALYZE no other transactions are updating that record so the update executes immediately. ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [ADMIN] What is syslog:duration reporting ... ?
On Fri, Aug 26, 2005 at 12:50:29AM +0100, Aldor wrote: > Aug 25 14:53:32 forgehouse-s1 postgres[23721]: [2-1] LOG: duration: > 567.559 ms statement: UPDATE session SET hit_time=now() WHERE > md5='7537b74eab488de54d6e0167d1919207'; > Aug 25 14:53:32 forgehouse-s1 postgres[23722]: [2-1] LOG: duration: > 565.966 ms statement: UPDATE session SET hit_time=now() WHERE > md5='d84613009a95296fb511c2cb051ad618'; > Aug 25 14:53:33 forgehouse-s1 postgres[23723]: [2-1] LOG: duration: > 1192.789 ms statement: UPDATE session SET hit_time=now() WHERE > md5='d84613009a95296fb511c2cb051ad618'; > Aug 25 14:53:53 forgehouse-s1 postgres[23727]: [2-1] LOG: duration: > 12159.162 ms statement: UPDATE session SET hit_time=now() WHERE > md5='d84613009a95296fb511c2cb051ad618'; > Aug 25 14:53:54 forgehouse-s1 postgres[23728]: [2-1] LOG: duration: > 3283.185 ms statement: UPDATE session SET hit_time=now() WHERE > md5='7537b74eab488de54d6e0167d1919207'; > Aug 25 14:53:57 forgehouse-s1 postgres[23729]: [2-1] LOG: duration: > 2116.516 ms statement: UPDATE session SET hit_time=now() WHERE > md5='7537b74eab488de54d6e0167d1919207'; > > Take a look to the timestamps... they are not really close to each other... Eh? The timestamps show that the updates *are* close to each other. What we don't know is whether this log excerpt shows all statements that were executed during its time frame. It might have been grep'ed from the full log file, or the log_min_duration_statement setting might be such that only statements lasting more than a certain amount of time are logged and we're not seeing similar updates that happened quickly, nor when any of the updates were committed. Marc, does my hypothesis of updates being blocked by other transactions sound plausible in your environment? How complete a log did you post -- is it everything, or are there other statements that you omitted or that weren't logged because of the log_min_duration_statement setting? -- Michael Fuhr ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [ADMIN] What is syslog:duration reporting ... ?
On Thu, 25 Aug 2005, Michael Fuhr wrote: On Fri, Aug 26, 2005 at 12:50:29AM +0100, Aldor wrote: Aug 25 14:53:32 forgehouse-s1 postgres[23721]: [2-1] LOG: duration: 567.559 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; Aug 25 14:53:32 forgehouse-s1 postgres[23722]: [2-1] LOG: duration: 565.966 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:33 forgehouse-s1 postgres[23723]: [2-1] LOG: duration: 1192.789 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:53 forgehouse-s1 postgres[23727]: [2-1] LOG: duration: 12159.162 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:54 forgehouse-s1 postgres[23728]: [2-1] LOG: duration: 3283.185 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; Aug 25 14:53:57 forgehouse-s1 postgres[23729]: [2-1] LOG: duration: 2116.516 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; Take a look to the timestamps... they are not really close to each other... Eh? The timestamps show that the updates *are* close to each other. What we don't know is whether this log excerpt shows all statements that were executed during its time frame. It might have been grep'ed from the full log file, or the log_min_duration_statement setting might be such that only statements lasting more than a certain amount of time are logged and we're not seeing similar updates that happened quickly, nor when any of the updates were committed. Marc, does my hypothesis of updates being blocked by other transactions sound plausible in your environment? How complete a log did you post -- is it everything, or are there other statements that you omitted or that weren't logged because of the log_min_duration_statement setting? I'm working on it from that perspective ... apparently, there has been no changes to teh database, only the application ... the weird thing is that the application/database on teh development server (much less powerful) isn't exhibiting the same problems, so I'm thinking there has to be somethign slightly different between the two that they aren't thinking of that they've made ... Going to have to do a code review next, see if they've maybe thrown in a TRANSACTION wouldn't realizing/thinking of it :( Thanks ... Marc G. Fournier Hub.Org Networking Services (http://www.hub.org) Email: [EMAIL PROTECTED] Yahoo!: yscrappy ICQ: 7615664 ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [ADMIN] What is syslog:duration reporting ... ?
Aug 25 14:53:33 forgehouse-s1 postgres[23723]: [2-1] LOG: duration: > 1192.789 ms statement: UPDATE session SET hit_time=now() WHERE > md5='d84613009a95296fb511c2cb051ad618'; > Aug 25 14:53:53 forgehouse-s1 postgres[23727]: [2-1] LOG: duration: > 12159.162 ms statement: UPDATE session SET hit_time=now() WHERE > md5='d84613009a95296fb511c2cb051ad618'; 20 seconds - 13 seconds (execution time) = 7 seconds So it also happens when they are not close to each other. The hint with the log_min_duration is a good idea. Michael Fuhr wrote: On Fri, Aug 26, 2005 at 12:50:29AM +0100, Aldor wrote: Aug 25 14:53:32 forgehouse-s1 postgres[23721]: [2-1] LOG: duration: 567.559 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; Aug 25 14:53:32 forgehouse-s1 postgres[23722]: [2-1] LOG: duration: 565.966 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:33 forgehouse-s1 postgres[23723]: [2-1] LOG: duration: 1192.789 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:53 forgehouse-s1 postgres[23727]: [2-1] LOG: duration: 12159.162 ms statement: UPDATE session SET hit_time=now() WHERE md5='d84613009a95296fb511c2cb051ad618'; Aug 25 14:53:54 forgehouse-s1 postgres[23728]: [2-1] LOG: duration: 3283.185 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; Aug 25 14:53:57 forgehouse-s1 postgres[23729]: [2-1] LOG: duration: 2116.516 ms statement: UPDATE session SET hit_time=now() WHERE md5='7537b74eab488de54d6e0167d1919207'; Take a look to the timestamps... they are not really close to each other... Eh? The timestamps show that the updates *are* close to each other. What we don't know is whether this log excerpt shows all statements that were executed during its time frame. It might have been grep'ed from the full log file, or the log_min_duration_statement setting might be such that only statements lasting more than a certain amount of time are logged and we're not seeing similar updates that happened quickly, nor when any of the updates were committed. Marc, does my hypothesis of updates being blocked by other transactions sound plausible in your environment? How complete a log did you post -- is it everything, or are there other statements that you omitted or that weren't logged because of the log_min_duration_statement setting? ---(end of broadcast)--- TIP 4: Have you searched our list archives? http://archives.postgresql.org
Re: [ADMIN] What is syslog:duration reporting ... ?
On Fri, Aug 26, 2005 at 02:27:04PM +0100, Aldor wrote: > Aug 25 14:53:33 forgehouse-s1 postgres[23723]: [2-1] LOG: duration: > > 1192.789 ms statement: UPDATE session SET hit_time=now() WHERE > > md5='d84613009a95296fb511c2cb051ad618'; > > > Aug 25 14:53:53 forgehouse-s1 postgres[23727]: [2-1] LOG: duration: > > 12159.162 ms statement: UPDATE session SET hit_time=now() WHERE > > md5='d84613009a95296fb511c2cb051ad618'; > > 20 seconds - 13 seconds (execution time) = 7 seconds > > So it also happens when they are not close to each other. Perhaps you're overlooking the possibility that the first update was part of a transaction that didn't commit until ~20 seconds after the update was issued, and that the second update was started sometime in between. Another possibility is that other transactions were happening but weren't logged because their statements executed in less time than the log_min_duration_statement setting (but the transactions themselves might have lasted much longer). Marc, what *is* the log_min_duration_statement setting? Here's a hypothetical example that would account for the above log entries, using T1, T2, and T3 for three different transactions (of which only T2 and T3 are shown in the log excerpt, and then only their long-lasting UPDATE statements): 14:53:29 T1 BEGIN 14:53:30 T1 UPDATE (completes immediately) 14:53:31 T2 BEGIN 14:53:32 T2 UPDATE (blocks because of T1's UPDATE) 14:53:33 T1 COMMIT (T2's UPDATE unblocks and is logged as taking 1192.789 ms) 14:53:40 T3 BEGIN 14:53:41 T3 UPDATE (blocks) 14:53:53 T2 COMMIT (T3's UPDATE unblocks and is logged as taking 12159.162 ms) Depending on the application, a transaction lasting 20 seconds or more might not be unreasonable (or it might indeed be unreasonable, yet still happening). But Marc will have to investigate to see what's really going on; I simply offer one possible explanation. -- Michael Fuhr ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
