Thread: transaction delays to apply
Hello All, I'm developing specialized message switching system and I've chosen to use PostgreSQL as general tool to handle transactions, store and manage all the data. This system has pretty strong timing requirements. For example, it must process not less than 10 messages per second. FYI: messages are short (aprx. 400-500 bytes length). Incoming message should be routed via special routing system to its destinations (i.e. one incoming message may be routed in dozens of channels at once). Normally this system works excellent with PostgreSQL database, the perfomance is quite impressive. BUT sometimes bad things happen (delays). For example: I have "log" table which contains all log entries for the system (warnings, errors, detailed routing info, rejections, etc). The table includes "timestamp" field and this field defaults to "now()": CREATE TABLE log ( id bigserial NOT NULL, "timestamp" timestamp without time zone NOT NULL DEFAULT now(), .. etc. So when incoming message is being processed, I do start new transaction and generate outgoing and log messages in this single transaction. Normally, viewing the log sorted by ID it comes in right timing order: ID timestamp 1 2009-08-08 00:00:00.111 2 2009-08-08 00:00:00.211 3 2009-08-08 00:01:00.311 etc. BUT it seems that rarely this transaction is being delayed to apply and log entry is being inserted in wrong order: ID timestamp 1 2009-08-08 00:00:00.111 2 2009-08-08 00:00:30.311 3 2009-08-08 00:00:00.211 Yep, that's right - sometimes for 30 seconds or even more. I do understand that there should be some delays with the database, but 30 seconds is unacceptable! Does anybody know any way to solve this? I did monitor the system running at full load (~20 messages per second) - postmaster's processes didn't eat more than 10-20% of CPU and memory. Neither did any of my application's processes. Best regards, Nick.
> Does anybody know any way to solve this? I did monitor the system > running at full load (~20 messages per second) - postmaster's processes > didn't eat more than 10-20% of CPU and memory. Neither did any of my > application's processes. now() like current_timestamp is the time of transaction start. If your client BEGINs, then idles for 30 seconds, then INSERTs, the timestamp in the insert will be from 30 second ago. Try statement_timestamp() or clock_timestamp().
Nickolay <nitro@zhukcity.ru> writes:
> BUT it seems that rarely this transaction is being delayed to apply and
> log entry is being inserted in wrong order:
> ID timestamp
> 1 2009-08-08 00:00:00.111
> 2 2009-08-08 00:00:30.311
> 3 2009-08-08 00:00:00.211
> Yep, that's right - sometimes for 30 seconds or even more.
You haven't provided enough information to let anyone guess at the
problem. Have you checked to see if one of the processes is blocking
on a lock, or perhaps there's a sudden spike in system load, or what?
Watching pg_stat_activity, pg_locks, and/or "vmstat 1" output during
one of these events might help narrow down what's happening.
regards, tom lane
Tom Lane wrote: > Nickolay <nitro@zhukcity.ru> writes: > >> BUT it seems that rarely this transaction is being delayed to apply and >> log entry is being inserted in wrong order: >> ID timestamp >> 1 2009-08-08 00:00:00.111 >> 2 2009-08-08 00:00:30.311 >> 3 2009-08-08 00:00:00.211 >> Yep, that's right - sometimes for 30 seconds or even more. >> > > You haven't provided enough information to let anyone guess at the > problem. Have you checked to see if one of the processes is blocking > on a lock, or perhaps there's a sudden spike in system load, or what? > Watching pg_stat_activity, pg_locks, and/or "vmstat 1" output during > one of these events might help narrow down what's happening. > > regards, tom lane > > The problem is that such thing happens very rare, and NOT at full load. I can't monitor the system all the time. Is there any way to investigate the situation by any of pgsql logs or enable something like full debug? I do have a row-level lock (SELECT...FOR UPDATE) on another table during this transaction, but one row are handled by not more than 2 processes at once and it should be very quick (SELECT, parse data and UPDATE). Thank you very much for you help! Best regards, Nick.
Tom Lane wrote: > Nickolay <nitro@zhukcity.ru> writes: > >> BUT it seems that rarely this transaction is being delayed to apply and >> log entry is being inserted in wrong order: >> ID timestamp >> 1 2009-08-08 00:00:00.111 >> 2 2009-08-08 00:00:30.311 >> 3 2009-08-08 00:00:00.211 >> Yep, that's right - sometimes for 30 seconds or even more. >> > > You haven't provided enough information to let anyone guess at the > problem. Have you checked to see if one of the processes is blocking > on a lock, or perhaps there's a sudden spike in system load, or what? > Watching pg_stat_activity, pg_locks, and/or "vmstat 1" output during > one of these events might help narrow down what's happening. > > regards, tom lane > > Thank you, guys. Problem's solved. I'm guilty and stupid :-) One of the SELECT's in the transaction was wrong. Its job was to select messages from archive by several conditions, including: date_time::date = now()::date (i.e. timestamp field "date_time" was being converted to date type). After first run, postgresql seems to fix my mistake by cache or something else and futher SELECT's are being executed in a matter of milliseconds. Fixed the statement to: date_time >= now()::date and now everything seems to work just fine even at first run. Best regards, Nick.