Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm List-Subscribe: List-Archive: List-Post: List-Help: , Sender: cygwin-owner AT cygwin DOT com Mail-Followup-To: cygwin AT cygwin DOT com Delivered-To: mailing list cygwin AT cygwin DOT com Message-ID: <005801c567b9$f5dcb4e0$1f3ca8c0@AlohaSunset.com> From: "Mark Pizzolato" To: Subject: strace data seems to show hang during socket close Date: Thu, 2 Jun 2005 14:27:28 -0700 MIME-Version: 1.0 Content-Type: text/plain; format=flowed; charset="iso-8859-1"; reply-type=original Content-Transfer-Encoding: 7bit X-IsSubscribed: yes I trying to debug an aparrent hang problem in clamav's clamd. Under my test load, I can usually get clamd to hang rather easily. Today I got lucky and managed to get an strace of the hang happening (usually the hang doesn't happen while stracing...). When this app hung, it stopped consuming any CPU cycles. Now, I'm trying to interpret the strace results to get a clue about what isn't working right. When clamd hung, the clamd log file ended with the following lines: Wed Jun 1 15:57:10 2005 -> stream 1753: OK Wed Jun 1 16:00:11 2005 -> ERROR: ScanStream 2043: accept timeout. Wed Jun 1 16:00:14 2005 -> ERROR: ScanStream 1289: accept timeout. I'm trying to understand why it appears that the two worker threads (0x95C and 0x490) seem to have "disappeared" and hung indefinately while attempting to close a socket. Why might this happen? strace was invoked with: strace --pid=3772 --output=clamd.strace --flush-period=30 --mask=all The end of the strace data contains. 311 528007410 [unknown (0x948)] clamd 3772 writev: 44 = write (3, 0x26CC500, 1), errno 90 247 528007657 [unknown (0x948)] clamd 3772 close: close (11) 1606 528009263 [unknown (0x948)] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close() 210 528009473 [unknown (0x948)] clamd 3772 close: 0 = close (11) 409 528009882 [unknown (0x948)] clamd 3772 time: 1117666631 = time (0) 1068 528010950 [unknown (0x948)] clamd 3772 _cygtls::remove: wait 0xFFFFFFFF 527 528011477 [unknown (0x948)] clamd 3772 _cygtls::remove: removed 0x26CF0A0 element 6 228 528011705 [unknown (0x948)] clamd 3772 _cygtls::remove: wait 0x0 26718851 554730556 [select_socket] clamd 3772 thread_socket: Win32 select returned 1 274 554730830 [select_socket] clamd 3772 thread_socket: s 0x102F7C28, testing fd 4 () 321 554731151 [select_socket] clamd 3772 thread_socket: read_ready 3275 554734426 [main] clamd 3772 select_stuff::wait: woke up. wait_ret 1. verifying 221 554734647 [main] clamd 3772 select_stuff::wait: gotone 1 131 554734778 [main] clamd 3772 select_stuff::wait: returning 0 605 554735383 [main] clamd 3772 select_stuff::cleanup: calling cleanup routines 175 554735558 [main] clamd 3772 socket_cleanup: si 0x10B48140 si->thread 0x610FFC60 185 554735743 [main] clamd 3772 socket_cleanup: sent a byte to exitsock 0x2C4, res 1 249 554735992 [main] clamd 3772 socket_cleanup: reading a byte from exitsock 0x2C4 528 554736520 [main] clamd 3772 socket_cleanup: recv returned 1 615 554737135 [main] clamd 3772 socket_cleanup: returning 133 554737268 [main] clamd 3772 peek_socket: considering handle 0x2F0 160 554737428 [main] clamd 3772 set_bits: me 0x102F7C28, testing fd 4 () 117 554737545 [main] clamd 3772 set_bits: ready 1 629 554738174 [main] clamd 3772 select_stuff::poll: returning 1 372 554738546 [main] clamd 3772 select_stuff::cleanup: calling cleanup routines 134 554738680 [main] clamd 3772 select_stuff::~select_stuff: deleting select records 435 554739115 [main] clamd 3772 fdsock: reset socket inheritance since winsock2_active 1 395 554739510 [main] clamd 3772 build_fh_pc: fh 0x61816738 156 554739666 [main] clamd 3772 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0 116 554739782 [main] clamd 3772 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000 111 554739893 [main] clamd 3772 fhandler_base::set_flags: filemode set to binary 110 554740003 [main] clamd 3772 fdsock: fd 6, name '', soc 0x3FC 109 554740112 [main] clamd 3772 fhandler_socket::accept: res 6 522 554740634 [main] clamd 3772 cygwin_accept: 6 = accept (4, 0x0, 0x0) 153999229 708739863 [unknown (0x490)] clamd 3772 select_stuff::wait: timed out 282 708740145 [unknown (0x490)] clamd 3772 select_stuff::wait: returning 1 129 708740274 [unknown (0x490)] clamd 3772 select_stuff::cleanup: calling cleanup routines 121 708740395 [unknown (0x490)] clamd 3772 socket_cleanup: si 0x10448370 si->thread 0x610FFC08 303 708740698 [unknown (0x490)] clamd 3772 socket_cleanup: sent a byte to exitsock 0x28C, res 1 1332 708742030 [select_socket] clamd 3772 thread_socket: Win32 select returned 1 213 708742243 [select_socket] clamd 3772 thread_socket: s 0x10222FB0, testing fd 5 () 122 708742365 [select_socket] clamd 3772 thread_socket: saw exitsock read 389 708742754 [unknown (0x490)] clamd 3772 socket_cleanup: reading a byte from exitsock 0x28C 263 708743017 [unknown (0x490)] clamd 3772 socket_cleanup: recv returned 1 250 708743267 [unknown (0x490)] clamd 3772 socket_cleanup: returning 120 708743387 [unknown (0x490)] clamd 3772 peek_socket: considering handle 0x7C 116 708743503 [unknown (0x490)] clamd 3772 peek_socket: adding read fd_set , fd 5 762 708744265 [unknown (0x490)] clamd 3772 peek_socket: adding except fd_set , fd 5 429 708744694 [unknown (0x490)] clamd 3772 peek_socket: WINSOCK_SELECT returned 0 155 708744849 [unknown (0x490)] clamd 3772 select_stuff::poll: returning 0 118 708744967 [unknown (0x490)] clamd 3772 select_stuff::cleanup: calling cleanup routines 203 708745170 [unknown (0x490)] clamd 3772 select_stuff::~select_stuff: deleting select records 705 708745875 [unknown (0x490)] clamd 3772 __set_winsock_errno: sendto:1239 - winsock error 10053 -> errno 113 148 708746023 [unknown (0x490)] clamd 3772 cygwin_sendto: -1 = sendto (29, 0x10CC870, 22, 0, 0x0, 0) 131 708746154 [unknown (0x490)] clamd 3772 time: 1117666811 = time (10CC5CC) 1383 708747537 [unknown (0x490)] clamd 3772 stat64: entering 163 708747700 [unknown (0x490)] clamd 3772 normalize_posix_path: src /var/log/clamd.log 119 708747819 [unknown (0x490)] clamd 3772 normalize_posix_path: /var/log/clamd.log = normalize_posix_path (/var/log/clamd.log) 122 708747941 [unknown (0x490)] clamd 3772 mount_info::conv_to_win32_path: conv_to_win32_path (/var/log/clamd.log) 1608 708749549 [unknown (0x490)] clamd 3772 set_flags: flags: binary (0x2) 14886 708764435 [unknown (0x490)] clamd 3772 mount_info::conv_to_win32_path: src_path /var/log/clamd.log, dst C:\cygwin\var\log\clamd.log, flags 0xA, rc 0 407 708764842 [unknown (0x490)] clamd 3772 symlink_info::check: not a symlink 1213 708766055 [unknown (0x490)] clamd 3772 symlink_info::check: 0 = symlink.check (C:\cygwin\var\log\clamd.log, 0x10CBF70) (0xA) 207 708766262 [unknown (0x490)] clamd 3772 path_conv::check: this->path(C:\cygwin\var\log\clamd.log), has_acls(1) 132 708766394 [unknown (0x490)] clamd 3772 build_fh_pc: fh 0x61814AC8 120 708766514 [unknown (0x490)] clamd 3772 stat_worker: (/var/log/clamd.log, 0x10CC5D0, 0, 0x61814AC8), file_attributes 32 174 708766688 [unknown (0x490)] clamd 3772 fhandler_base::open: (C:\cygwin\var\log\clamd.log, 0x110000) 268 708766956 [unknown (0x490)] clamd 3772 fhandler_base::set_flags: flags 0x110000, supplied_bin 0x10000 512 708767468 [unknown (0x490)] clamd 3772 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000 264 708767732 [unknown (0x490)] clamd 3772 fhandler_base::set_flags: filemode set to binary 140 708767872 [unknown (0x490)] clamd 3772 fhandler_base::open: 0 = NtCreateFile (0x20, 20080, C:\cygwin\var\log\clamd.log, io, NULL, 0, 7, 1, 4000, NULL, 0) 120 708767992 [unknown (0x490)] clamd 3772 fhandler_base::open: 1 = fhandler_base::open (C:\cygwin\var\log\clamd.log, 0x110000) 118 708768110 [unknown (0x490)] clamd 3772 fhandler_base::open_fs: 1 = fhandler_disk_file::open (C:\cygwin\var\log\clamd.log, 0x10000) 158 708768268 [unknown (0x490)] clamd 3772 get_file_attribute: file: C:\cygwin\var\log\clamd.log 910 708769178 [unknown (0x490)] clamd 3772 cygpsid::debug_print: get_sids_info: owner SID = S-1-5-21-1645522239-926492609-682003330-1112 830 708770008 [unknown (0x490)] clamd 3772 cygpsid::debug_print: get_sids_info: group SID = S-1-5-32-545 171 708770179 [unknown (0x490)] clamd 3772 get_info_from_sd: ACL 1A0, uid 11112, gid 10545 416 708770595 [unknown (0x490)] clamd 3772 fhandler_base::fstat_helper: 0 = fstat (, 0x10CC5D0) st_atime=429E3D47 st_size=23601972, st_mode=0x81A0, st_ino=22949, sizeof=96 1592 708772187 [unknown (0x490)] clamd 3772 fhandler_base::close: closing '/var/log/clamd.log' handle 0x20 268 708772455 [unknown (0x490)] clamd 3772 stat_worker: 0 = (/var/log/clamd.log, 0x10CC5D0) 850 708773305 [unknown (0x490)] clamd 3772 fhandler_base::lseek: lseek (/var/log/clamd.log, 0, 2) 126 708773431 [unknown (0x490)] clamd 3772 fhandler_base::lseek: setting file pointer to 0 (high), 0 (low) 130 708773561 [unknown (0x490)] clamd 3772 lseek64: 23601972 = lseek (3, 0, 2) 149 708773710 [unknown (0x490)] clamd 3772 writev: writev (3, 0x10CC500, 1) 130 708773840 [unknown (0x490)] clamd 3772 fhandler_base::write: binary write 265 708774105 [unknown (0x490)] clamd 3772 writev: 68 = write (3, 0x10CC500, 1), errno 113 236 708774341 [unknown (0x490)] clamd 3772 close: close (5) 345 708774686 [unknown (0x490)] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close() 164 708774850 [unknown (0x490)] clamd 3772 close: 0 = close (5) 126 708774976 [unknown (0x490)] clamd 3772 close: close (29) 1046 708776022 [unknown (0x490)] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close() 206 708776228 [unknown (0x490)] clamd 3772 close: 0 = close (29) 2680015 711456243 [unknown (0x95C)] clamd 3772 select_stuff::wait: timed out 592 711456835 [unknown (0x95C)] clamd 3772 select_stuff::wait: returning 1 190 711457025 [unknown (0x95C)] clamd 3772 select_stuff::cleanup: calling cleanup routines 1616 711458641 [unknown (0x95C)] clamd 3772 socket_cleanup: si 0x101B67A8 si->thread 0x610FFC34 274 711458915 [unknown (0x95C)] clamd 3772 socket_cleanup: sent a byte to exitsock 0x214, res 1 236 711459151 [select_socket] clamd 3772 thread_socket: Win32 select returned 1 20814 711479965 [select_socket] clamd 3772 thread_socket: s 0x10BA70B8, testing fd 8 () 206 711480171 [select_socket] clamd 3772 thread_socket: saw exitsock read 908 711481079 [unknown (0x95C)] clamd 3772 socket_cleanup: reading a byte from exitsock 0x214 184 711481263 [unknown (0x95C)] clamd 3772 socket_cleanup: recv returned 1 757 711482020 [unknown (0x95C)] clamd 3772 socket_cleanup: returning 193 711482213 [unknown (0x95C)] clamd 3772 peek_socket: considering handle 0x158 159 711482372 [unknown (0x95C)] clamd 3772 peek_socket: adding read fd_set , fd 8 122 711482494 [unknown (0x95C)] clamd 3772 peek_socket: adding except fd_set , fd 8 156 711482650 [unknown (0x95C)] clamd 3772 peek_socket: WINSOCK_SELECT returned 0 126 711482776 [unknown (0x95C)] clamd 3772 select_stuff::poll: returning 0 558 711483334 [unknown (0x95C)] clamd 3772 select_stuff::cleanup: calling cleanup routines 175 711483509 [unknown (0x95C)] clamd 3772 select_stuff::~select_stuff: deleting select records 4210 711487719 [unknown (0x95C)] clamd 3772 __set_winsock_errno: sendto:1239 - winsock error 10053 -> errno 113 162 711487881 [unknown (0x95C)] clamd 3772 cygwin_sendto: -1 = sendto (30, 0x14CC870, 22, 0, 0x0, 0) 132 711488013 [unknown (0x95C)] clamd 3772 time: 1117666814 = time (14CC5CC) 1376 711489389 [unknown (0x95C)] clamd 3772 stat64: entering 132 711489521 [unknown (0x95C)] clamd 3772 normalize_posix_path: src /var/log/clamd.log 119 711489640 [unknown (0x95C)] clamd 3772 normalize_posix_path: /var/log/clamd.log = normalize_posix_path (/var/log/clamd.log) 252 711489892 [unknown (0x95C)] clamd 3772 mount_info::conv_to_win32_path: conv_to_win32_path (/var/log/clamd.log) 138 711490030 [unknown (0x95C)] clamd 3772 set_flags: flags: binary (0x2) 123 711490153 [unknown (0x95C)] clamd 3772 mount_info::conv_to_win32_path: src_path /var/log/clamd.log, dst C:\cygwin\var\log\clamd.log, flags 0xA, rc 0 330 711490483 [unknown (0x95C)] clamd 3772 symlink_info::check: not a symlink 181 711490664 [unknown (0x95C)] clamd 3772 symlink_info::check: 0 = symlink.check (C:\cygwin\var\log\clamd.log, 0x14CBF70) (0xA) 126 711490790 [unknown (0x95C)] clamd 3772 path_conv::check: this->path(C:\cygwin\var\log\clamd.log), has_acls(1) 431 711491221 [unknown (0x95C)] clamd 3772 build_fh_pc: fh 0x618156F8 199 711491420 [unknown (0x95C)] clamd 3772 stat_worker: (/var/log/clamd.log, 0x14CC5D0, 0, 0x618156F8), file_attributes 32 141 711491561 [unknown (0x95C)] clamd 3772 fhandler_base::open: (C:\cygwin\var\log\clamd.log, 0x110000) 260 711491821 [unknown (0x95C)] clamd 3772 fhandler_base::set_flags: flags 0x110000, supplied_bin 0x10000 160 711491981 [unknown (0x95C)] clamd 3772 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000 123 711492104 [unknown (0x95C)] clamd 3772 fhandler_base::set_flags: filemode set to binary 289 711492393 [unknown (0x95C)] clamd 3772 fhandler_base::open: 0 = NtCreateFile (0x428, 20080, C:\cygwin\var\log\clamd.log, io, NULL, 0, 7, 1, 4000, NULL, 0) 145 711492538 [unknown (0x95C)] clamd 3772 fhandler_base::open: 1 = fhandler_base::open (C:\cygwin\var\log\clamd.log, 0x110000) 120 711492658 [unknown (0x95C)] clamd 3772 fhandler_base::open_fs: 1 = fhandler_disk_file::open (C:\cygwin\var\log\clamd.log, 0x10000) 156 711492814 [unknown (0x95C)] clamd 3772 get_file_attribute: file: C:\cygwin\var\log\clamd.log 427 711493241 [unknown (0x95C)] clamd 3772 cygpsid::debug_print: get_sids_info: owner SID = S-1-5-21-1645522239-926492609-682003330-1112 1077 711494318 [unknown (0x95C)] clamd 3772 cygpsid::debug_print: get_sids_info: group SID = S-1-5-32-545 237 711494555 [unknown (0x95C)] clamd 3772 get_info_from_sd: ACL 1A0, uid 11112, gid 10545 230 711494785 [unknown (0x95C)] clamd 3772 fhandler_base::fstat_helper: 0 = fstat (, 0x14CC5D0) st_atime=429E3DFD st_size=23602040, st_mode=0x81A0, st_ino=22949, sizeof=96 124 711494909 [unknown (0x95C)] clamd 3772 fhandler_base::close: closing '/var/log/clamd.log' handle 0x428 182 711495091 [unknown (0x95C)] clamd 3772 stat_worker: 0 = (/var/log/clamd.log, 0x14CC5D0) 1549 711496640 [unknown (0x95C)] clamd 3772 fhandler_base::lseek: lseek (/var/log/clamd.log, 0, 2) 553 711497193 [unknown (0x95C)] clamd 3772 fhandler_base::lseek: setting file pointer to 0 (high), 0 (low) 230 711497423 [unknown (0x95C)] clamd 3772 lseek64: 23602040 = lseek (3, 0, 2) 133 711497556 [unknown (0x95C)] clamd 3772 writev: writev (3, 0x14CC500, 1) 131 711497687 [unknown (0x95C)] clamd 3772 fhandler_base::write: binary write 131 711497818 [unknown (0x95C)] clamd 3772 writev: 68 = write (3, 0x14CC500, 1), errno 113 355 711498173 [unknown (0x95C)] clamd 3772 close: close (8) 368 711498541 [unknown (0x95C)] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close() 164 711498705 [unknown (0x95C)] clamd 3772 close: 0 = close (8) 124 711498829 [unknown (0x95C)] clamd 3772 close: close (30) 220 711499049 [unknown (0x95C)] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close() 148 711499197 [unknown (0x95C)] clamd 3772 close: 0 = close (30) Below corresponds to a kill -9 3772 I did some hours after the above output was produced. -39462844 672036353 [sig] clamd 3772 sigpacket::process: signal 9 processing 278 672036631 [sig] clamd 3772 sigpacket::process: signal 9, about to call do_exit 409 672037040 [sig] clamd 3772 signal_exit: about to call do_exit (9) 130 672037170 [sig] clamd 3772 do_exit: do_exit (9), exit_state 0 36124 672073294 [sig] clamd 3772 void: 0x0 = signal (20, 0x1) 199 672073493 [sig] clamd 3772 void: 0x405170 = signal (1, 0x1) 119 672073612 [sig] clamd 3772 void: 0x405170 = signal (2, 0x1) 111 672073723 [sig] clamd 3772 void: 0x0 = signal (3, 0x1) 188 672073911 [sig] clamd 3772 fhandler_console::close: decremented open_fhs, now 3 157 672074068 [sig] clamd 3772 fhandler_console::close: decremented open_fhs, now 2 150 672074218 [sig] clamd 3772 fhandler_console::close: decremented open_fhs, now 1 662 672074880 [sig] clamd 3772 fhandler_base::close: closing '/var/log/clamd.log' handle 0x33C 680 672075560 [sig] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close() 423 672075983 [sig] clamd 3772 fhandler_socket::close: 0 = fhandler_socket::close() 305 672076288 [sig] clamd 3772 sigproc_terminate: entering 147 672076435 [sig] clamd 3772 proc_terminate: n Thanks for any comments, observations or advise. - Mark Pizzolato -- Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple Problem reports: http://cygwin.com/problems.html Documentation: http://cygwin.com/docs.html FAQ: http://cygwin.com/faq/