logger process infinite loop

From: Jeff Janes <jeff(dot)janes(at)gmail(dot)com>
To: pgsql-hackers <pgsql-hackers(at)postgresql(dot)org>, Andres Freund <andres(at)anarazel(dot)de>
Subject: logger process infinite loop
Date: 2016-03-19 04:59:01
Message-ID: CAMkU=1zGxREwoyaCrp_CHadEB+dPgpVyKBysCJ+6xP9gCOvAuw@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

While testing some patches on my laptop, I noticed my knee getting
uncomfortably warm. It turns out I has accumulating deranged logging
processes, needing kill -9 to get rid of them.

The culprit is:

commit c4901a1e03a7730e4471fd1143f1caf79695493d
Author: Andres Freund <andres(at)anarazel(dot)de>
Date: Fri Mar 18 11:43:59 2016 -0700

Only clear latch self-pipe/event if there is a pending notification.

All I need to do to reproduce it is turn logging_collector = on,
then:
pg_ctl start
pg_ctl stop

A strace of a logger process shows:

poll([{fd=10, events=POLLIN}, {fd=7, events=POLLIN}], 2, 9771863) = 1
([{fd=7, revents=POLLHUP}])
poll([{fd=10, events=POLLIN}, {fd=7, events=POLLIN}], 2, 9771863) = 1
([{fd=7, revents=POLLHUP}])
poll([{fd=10, events=POLLIN}, {fd=7, events=POLLIN}], 2, 9771863) = 1
([{fd=7, revents=POLLHUP}])
poll([{fd=10, events=POLLIN}, {fd=7, events=POLLIN}], 2, 9771863) = 1
([{fd=7, revents=POLLHUP}])
poll([{fd=10, events=POLLIN}, {fd=7, events=POLLIN}], 2, 9771863) = 1
([{fd=7, revents=POLLHUP}])
poll([{fd=10, events=POLLIN}, {fd=7, events=POLLIN}], 2, 9771863) = 1
([{fd=7, revents=POLLHUP}])
poll([{fd=10, events=POLLIN}, {fd=7, events=POLLIN}], 2, 9771862) = 1
([{fd=7, revents=POLLHUP}])
poll([{fd=10, events=POLLIN}, {fd=7, events=POLLIN}], 2, 9771862) = 1
([{fd=7, revents=POLLHUP}])
poll([{fd=10, events=POLLIN}, {fd=7, events=POLLIN}], 2, 9771862) = 1
([{fd=7, revents=POLLHUP}])
poll([{fd=10, events=POLLIN}, {fd=7, events=POLLIN}], 2, 9771862) = 1
([{fd=7, revents=POLLHUP}])

And a backtrace shows:

(gdb) bt full
#0 0x00007fce93f90050 in __poll_nocancel () from /lib64/libc.so.6
No symbol table info available.
#1 0x000000000065a52a in WaitLatchOrSocket (latch=0xc179c4
<LocalLatchData>, wakeEvents=11, sock=7, timeout=7259000) at
pg_latch.c:350
result = 0
rc = <optimized out>
start_time = {tv_sec = 1458363541, tv_usec = 583339}
cur_time = {tv_sec = 19, tv_usec = 795497}
cur_timeout = 7239205
pfds = {{fd = 10, events = 1, revents = 0}, {fd = 7, events =
1, revents = 16}, {fd = 222842297, events = 32766, revents = 0}}
nfds = 2
__func__ = "WaitLatchOrSocket"
#2 0x000000000066b64f in SysLoggerMain (argv=<optimized out>,
argc=<optimized out>) at syslogger.c:424
time_based_rotation = <optimized out>
size_rotation_for = <optimized out>
cur_timeout = <optimized out>
rc = <optimized out>
logbuffer = "\000\000K\000\362\021\000\000t4594 00000
2016-03-18 21:59:01.583 PDT LOG: database system is shut
down\nbuffers (0.0%); 0 transaction log file(s) added, 0 removed, 0
recycled; write=0.000 s, sync=0.000 s, total=0.001 s; "...
bytes_in_logbuffer = 0
currentLogDir = 0x26ef130 "pg_log"
currentLogFilename = 0x26ef200 "postgresql-%Y-%m-%d_%H%M%S.log"
currentLogRotationAge = 1440
now = 1458363541
#3 0x000000000066bdfb in SysLogger_Start () at syslogger.c:600
sysloggerPid = 0
filename = 0x0
__func__ = "SysLogger_Start"
#4 0x000000000066a878 in PostmasterMain (argc=argc(at)entry=1,
argv=argv(at)entry=0x26d5a10) at postmaster.c:1208
opt = <optimized out>
status = <optimized out>
userDoption = <optimized out>
listen_addr_saved = <optimized out>
i = <optimized out>
output_config_variable = <optimized out>
__func__ = "PostmasterMain"
#5 0x000000000047cd1e in main (argc=1, argv=0x26d5a10) at main.c:228

Cheers,

Jeff

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Peter Geoghegan 2016-03-19 05:00:22 Re: WIP: Covering + unique indexes.
Previous Message Amit Kapila 2016-03-19 04:28:43 Re: Patch: fix lock contention for HASHHDR.mutex