[1.7] rsync hanging and spinning on cpu reprise

["John P. Rouillard" <rouilj at cs dot umb dot edu>]

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