This is the mail archive of the cygwin mailing list for the Cygwin project.
Index Nav: | [Date Index] [Subject Index] [Author Index] [Thread Index] | |
---|---|---|
Message Nav: | [Date Prev] [Date Next] | [Thread Prev] [Thread Next] |
Other format: | [Raw text] |
Hi all: It looks like I can get rsync to spin on the cpu with the latest release cygwin 1.7. I have attached cygcheck.txt for those interested (hopefully it will not be encoded). I start rsync with: strace -o trace.txt rsync -v -v --daemon --config=etc/rsyncd.conf --no-detach --log-file=diagnostic.txt where etc/rsyncd.conf is: use chroot = false strict modes = false pid file = rsyncd.pid address = 127.0.0.1 [C] path = /cygdrive/C/ auth users = Administrator backup secrets file = secret.txt I then ssh to a remote host: ssh -R 2873:127.0.0.1:873 host.example.com and set it up to forward from port 2873 on the remote machine to port 873 (the rsync daemon port) on my laptop. Then I connect from the remote machine to that port using backuppc (although the same thing happens if I connect using a native rsync client). Things proceed normally till it attempts to read: Documents and Settings/Administrator/Local Settings/Application Data/Microsoft/Media Player/CurrentDatabase_59R.wmdb at which point it consumes 50% of the cpu (usually it was consuming 20-25%) and the sshd also consumes 50% of the cpu. The strace at this point shows: [...] 300 551944352 [main] rsync 9740 fhandler_base::open_fs: 1 = fhandler_disk_file::open (\??\C:\Documents and Settings\Administrator\Local Settings\Application Data\Microsoft\Media Player\CurrentDatabase_59R.wmdb, 0x10000) 279 551944631 [main] rsync 9740 open: 4 = open (Documents and Settings/Administrator/Local Settings/Application Data/Microsoft/Media Player/CurrentDatabase_59R.wmdb, 0x10000) 425 551945056 [main] rsync 9740 cygpsid::debug_print: get_sids_info: owner SID = S-1-5-21-1407653522-934166297-3473930260-500 273 551945329 [main] rsync 9740 cygpsid::debug_print: get_sids_info: group SID = S-1-5-21-1407653522-934166297-3473930260-513 269 551945598 [main] rsync 9740 get_info_from_sd: ACL 1C0, uid 500, gid 513 281 551945879 [main] rsync 9740 fhandler_base::fstat_helper: 0 = fstat (, 0x228CC8) st_atime=4AC50B10 st_size=720896, st_mode=0x81C0, st_ino=281474976717848, sizeof=96 265 551946144 [main] rsync 9740 fstat64: 0 = fstat (4, 0x228CC8) 301 551946445 [main] rsync 9740 mmap64: addr 0, len 327680, prot 3, flags 22, fd -1, off 0 288 551946733 [main] rsync 9740 mmap64: 0x7FD30000 = mmap() 282 551947015 [main] rsync 9740 readv: readv (4, 0x226A44, 1) blocking, sigcatchers 6 279 551947294 [main] rsync 9740 readv: no need to call ready_for_read 636 551947930 [main] rsync 9740 fhandler_base::read: returning 262144, binary mode 261 551948191 [main] rsync 9740 readv: 262144 = readv (4, 0x226A44, 1), errno 0 281 551948472 [main] rsync 9740 cygwin_select: 4, 0x0, 0x225614, 0x225604, 0x2255FC 298 551948770 [main] rsync 9740 dtable::select_write: fd 3 262 551949032 [main] rsync 9740 dtable::select_except: fd 3 279 551949311 [main] rsync 9740 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms 60000 268 551949579 [main] rsync 9740 cygwin_select: sel.always_ready 0 302 551949881 [main] rsync 9740 start_thread_socket: stuff_start 0x225160 519 551950400 [main] rsync 9740 select_stuff::wait: m 2, ms 60000 335 551950735 [select_socket] rsync 9740 thread_socket: stuff_start 0x225160 273 551951008 [select_socket] rsync 9740 peek_socket: read_ready: 0, write_ready: 1, except_ready: 0 250 551951258 [select_socket] rsync 9740 thread_socket: leaving thread_socket 250 551951508 [main] rsync 9740 select_stuff::wait: woke up. wait_ret 1. verifying 253 551951761 [main] rsync 9740 select_stuff::wait: gotone 1 242 551952003 [main] rsync 9740 select_stuff::wait: returning 0 245 551952248 [main] rsync 9740 select_stuff::cleanup: calling cleanup routines 241 551952489 [main] rsync 9740 socket_cleanup: si 0x1006B290 si->thread 0x6114B1B0 321 551952810 [main] rsync 9740 socket_cleanup: returning 251 551953061 [main] rsync 9740 peek_socket: read_ready: 0, write_ready: 1, except_ready: 0 253 551953314 [main] rsync 9740 set_bits: me 0x1006B260, testing fd 3 () 242 551953556 [main] rsync 9740 set_bits: ready 1 243 551953799 [main] rsync 9740 select_stuff::poll: returning 1 240 551954039 [main] rsync 9740 select_stuff::cleanup: calling cleanup routines 244 551954283 [main] rsync 9740 select_stuff::~select_stuff: deleting select records 267 551954550 [main] rsync 9740 writev: writev (3, 0x2251A4, 1) 371 551954921 [main] rsync 9740 writev: 4 = write (3, 0x2251A4, 1), errno 0 259 551955180 [main] rsync 9740 cygwin_select: 4, 0x0, 0x225614, 0x225604, 0x2255FC 288 551955468 [main] rsync 9740 dtable::select_write: fd 3 247 551955715 [main] rsync 9740 dtable::select_except: fd 3 252 551955967 [main] rsync 9740 cygwin_select: to->tv_sec 60, to->tv_usec 0, ms 60000 281 551956248 [main] rsync 9740 cygwin_select: sel.always_ready 0 290 551956538 [main] rsync 9740 start_thread_socket: stuff_start 0x225160 293 551956831 [main] rsync 9740 select_stuff::wait: m 2, ms 60000 264 551957095 [select_socket] rsync 9740 thread_socket: stuff_start 0x225160 274 551957369 [select_socket] rsync 9740 peek_socket: read_ready: 0, write_ready: 1, except_ready: 0 260 551957629 [select_socket] rsync 9740 thread_socket: leaving thread_socket 275 551957904 [main] rsync 9740 select_stuff::wait: woke up. wait_ret 1. verifying 263 551958167 [main] rsync 9740 select_stuff::wait: gotone 1 367 551958534 [main] rsync 9740 select_stuff::wait: returning 0 511 551959045 [main] rsync 9740 select_stuff::cleanup: calling cleanup routines 273 551959318 [main] rsync 9740 socket_cleanup: si 0x1006B290 si->thread 0x6114B1B0 509 551959827 [main] rsync 9740 socket_cleanup: returning 511 551959045 [main] rsync 9740 select_stuff::cleanup: calling cleanup routines 273 551959318 [main] rsync 9740 socket_cleanup: si 0x1006B290 si->thread 0x6114B1B0 509 551959827 [main] rsync 9740 socket_cleanup: returning There is more of this sort of peek -> socket cleanup. I can send the full strace on request. One odd thing is that trying to connect strace to the hung rsync pid doesn't result in any output. As a result I used strace on the parent (and not the child) process to get the output above. The process monitor from sysinternals shows: Time process pid operation path 4:11:40.3474968 rsync.exe 8908 TCP Send localhost:873 -> localhost:3076 SUCCESS Length: 4092 4:11:40.3474982 rsync.exe 8908 TCP Send localhost:873 -> localhost:3076 SUCCESS Length: 4 4:11:40.3475412 rsync.exe 8908 TCP Send localhost:873 -> localhost:3076 SUCCESS Length: 4092 4:11:40.3475426 rsync.exe 8908 TCP Send localhost:873 -> localhost:3076 SUCCESS Length: 4 4:11:40.3475440 rsync.exe 8908 TCP Send localhost:873 -> localhost:3076 SUCCESS Length: 4092 4:11:40.3475454 rsync.exe 8908 TCP Send localhost:873 -> localhost:3076 SUCCESS Length: 4 4:11:40.3489841 rsync.exe 8908 TCP Send localhost:873 -> localhost:3076 SUCCESS Length: 4092 4:11:40.3550718 rsync.exe 8908 TCP Send localhost:873 -> localhost:3076 SUCCESS Length: 4 4:11:45.6890664 rsync.exe 8908 TCP Retransmit localhost:873 -> localhost:3076 SUCCESS Length: 0 4:11:46.2925733 rsync.exe 8908 TCP Retransmit localhost:873 -> localhost:3076 SUCCESS Length: 0 4:11:47.4995890 rsync.exe 8908 TCP Retransmit localhost:873 -> localhost:3076 SUCCESS Length: 0 4:11:49.9136179 rsync.exe 8908 TCP Retransmit localhost:873 -> localhost:3076 SUCCESS Length: 0 4:11:54.6410969 rsync.exe 8908 TCP Retransmit localhost:873 -> localhost:3076 SUCCESS Length: 0 4:12:23.5088838 rsync.exe 8908 TCP Retransmit localhost:873 -> localhost:3076 SUCCESS Length: 0 4:13:01.9322105 rsync.exe 8908 TCP Retransmit localhost:873 -> localhost:3076 SUCCESS Length: 0 4:13:48.8806902 rsync.exe 8908 TCP Disconnect localhost:873 -> localhost:3076 SUCCESS Length: 0 4:13:48.8836507 rsync.exe 9740 Thread Exit SUCCESS Thread ID: 9820, User Time: 0.0156250, Kernel Time: 0.4687500 the thread exit is where I killed it. Sysinternals Process Explorer (not process monitor) shows the rsync process happily opening and closing files until it opens the .wmdb file at which point it's cpu use spikes and no file handle changes seem to occur. When this mode is hit, the ssh session is frozen (killing rsync frees the ssh session for interactive use). So what's the next step to try to debug this? -- -- rouilj John Rouillard =========================================================================== My employers don't acknowledge my existence much less my opinions.
Attachment:
cygcheck.txt
Description: cygcheck output
-- Problem reports: http://cygwin.com/problems.html FAQ: http://cygwin.com/faq/ Documentation: http://cygwin.com/docs.html Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
Index Nav: | [Date Index] [Subject Index] [Author Index] [Thread Index] | |
---|---|---|
Message Nav: | [Date Prev] [Date Next] | [Thread Prev] [Thread Next] |