Saturday, March 14, 2015

long term monitoring communication between PostgreSQL client and PostgreSQL server

We have some issue with our application and pgbouncer. We detect some new errors with very low frequency. One possibility how to detect a reason of these issues is monitoring the communication between our application and Postgres. I found a great tool pgShark. But I had to solve two issues.
  1. I have to reduce logged content - lot of messages are unimportant for my purpose or generate lot of content.  pgs-debug hasn't any option for it, so I had to modify source code. You can comment unwanted method. I disabled: Bind, BindComplete, CopyData, DataRow, Describe, Parse, ParseComplete, RowDescription, Sync. After this change the compressed log was few GB per day.
  2. I had a output (log) with attached timestamp. I can do it simply in bash:
    | while read line; do echo `date +"%T.%3N"` $line; done | 
I wrote a line:
unbuffer ./pgs-debug --host -i lo --port 6432 | while read line; do echo `date +"%d %T.%3N"` $line; done | gzip > /mnt/large/pgsharklog.gz

It does what I need:
12:55:13.407 P=1425556513.403313, s=288765600856048 type=SSLRequest, F -> B
12:55:13.408 SSL REQUEST
12:55:13.411 P=1425556513.403392, s=288765600856048 type=SSLAnswer, B -> F
12:55:13.412 SSL BACKEND ANSWER: N
12:55:13.415 P=1425556513.403486, s=288765600856048 type=StartupMessage, F -> B
12:55:13.416 STARTUP MESSAGE version: 3
12:55:13.418 database=db_lc3hfmn22q8vdt6mhopr2wj4zskyaous
12:55:13.419 application_name=starjoin
12:55:13.420 user=beard
12:55:13.423 P=1425556513.403526, s=288765600856048 type=AuthenticationMD5Password, B -> F
12:55:13.424 AUTHENTIFICATION REQUEST code=5 (MD5 salt='fe45f1a1')
12:55:13.426 P=1425556513.403577, s=288765600856048 type=PasswordMessage, F -> B
12:55:13.428 PASSWORD MESSAGE password=md5a0cd0711e0e191467bca6e94c03fb50f
12:55:13.430 P=1425556513.403614, s=288765600856048 type=AuthenticationOk, B -> F
12:55:13.434 P=1425556513.403614, s=288765600856048 type=ParameterStatus, B -> F
12:55:13.435 PARAMETER STATUS name='integer_datetimes', value='on'
12:55:13.437 P=1425556513.403614, s=288765600856048 type=ParameterStatus, B -> F
12:55:13.439 PARAMETER STATUS name='IntervalStyle', value='postgres'


At March 14, 2015 at 7:21 AM , Anonymous Anonymous said...

Nice but I think your pgShark link is broken.

At March 14, 2015 at 10:58 AM , Blogger Pavel Stěhule said...

fixed, thank you

At March 15, 2015 at 7:32 AM , OpenID asjo said...

If you log a lot, forking a process to run date for every line can be expensive. Simple solution(s):

At March 16, 2015 at 6:18 AM , Blogger ioguix said...


Nice ideas to add a timestamp, maybe it worth a line_prefix option in pgs-debug. Same thing to disable not wanted messages types.

I'll try to find some time to push your ideas in pgshark. In the meantime, do not hesitate to create issues or push requests on github!



Post a Comment

Subscribe to Post Comments [Atom]

Links to this post:

Create a Link

<< Home