while trying to find the reason for a long running rsync using strace, i came up to this strange strace output: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- -0.01 374.316425 662507 565 mmap2 -0.00 362.010131 661810 547 munmap -0.00 319.291945 148026 2157 mkdir -0.00 89.232056 30115 2963 rmdir -0.00 20.681387 382989 54 symlink -0.00 19.997709 416619 48 48 access -0.00 11.622611 683683 17 fcntl64 -0.00 5.640381 470032 12 mremap -0.00 4.785781 683683 7 mprotect -0.00 4.785776 398815 12 rt_sigaction -0.00 2.051049 683683 3 socketpair -0.00 1.367366 683683 2 chdir -0.00 1.367366 683683 2 umask -0.00 1.367366 683683 2 dup2 -0.00 1.367366 683683 2 clone -0.00 0.683683 683683 1 execve -0.00 0.683683 683683 1 gettimeofday -0.00 0.683683 683683 1 rt_sigprocmask -0.00 0.683683 683683 1 getcwd -0.00 0.683683 683683 1 geteuid32 -0.00 0.683683 683683 1 getegid32 -0.00 0.683683 683683 1 set_thread_area -0.00 0.341868 42734 8 5 waitpid 0.00 -0.170922 4294796374 1 kill 0.00 -0.341844 4294796375 2 1 sigreturn 0.03 -2524.915530 288799 6129 brk 0.05 -3382.978429 38507 23684 lchown32 0.07 -4838.841395 4293612638 3572 setxattr 0.11 -7898.536367 6783 101932 readlink 0.18 -12961.787912 4294966289 76239 chmod 0.18 -13257.275239 4294962486 77403 rename 0.18 -13309.783871 4294961808 77410 utimensat 0.18 -13338.157417 4294961438 77356 fchmod 0.29 -21606.599743 4294965824 89460 link 0.36 -26854.241957 4294960191 152618 fstat64 0.78 -57498.443889 4294954619 131242 unlink 2.16 -159555.612190 4294965578 373362 write 2.21 -163374.434599 4294966808 338871 read 2.79 -206468.699722 4294966446 364536 2 select 3.24 -239785.116270 1224 598951 openat 3.83 -283172.976801 355 831029 601056 open 3.84 -284432.128072 4294966134 828934 close 6.54 -483815.923609 1264 1199055 getdents64 15.05 -1113512.079222 4294967051 4541369 1 stat64 22.87 -1692178.379677 7 5222958 4539580 getxattr 35.08 -2595524.340762 4294967137 8503342 46909 lstat64 ------ ----------- ----------- --------- --------- ---------------- 100.00 -7398066.753075 23625863 5187602 total commandline is: strace -f -o /tmp/strace.log -c \ rsync --archive --one-file-system --acls --numeric-ids --omit-dir-times --delete --delete-during \ --human-readable --filter ": .rsync" -i \ --link-dest=/mnt/storage-2/backup/archive/daily/01 \ /mnt/storage-2/backup/current/ /mnt/storage-2/backup/archive/daily/00/; looks like most of the syscalls returned before they got called ;-) perhaps an integer overflow issue, because the big values are near to 2^32 ? this happens not every time but mostly. during this process no IO-errors are reported (dmesg,syslog,...). if i repeat this rsync using another harddisk in the same machine (same vendor/model) the output of strace looks plausible. but even if the harddisk could be the cause (both hd's have similar throughput reported by hdparm, and no errors reported so far), the strace output should _not_ contain negative values. re-emerging strace dit not help. strace is version 4.9; found these similar reports: http://marc.info/?l=strace&m=113145768301827 https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=500138 how to fix ? Thanks, Nico Reproducible: Sometimes Steps to Reproduce: see "description" Actual Results: see "description" Expected Results: something like that: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 38.83 1.527855 2 751876 617634 open 30.44 1.197746 0 8633933 35624 lstat64 10.91 0.429286 2 273155 write 8.42 0.331221 1 347845 read 6.74 0.265374 0 1202263 getdents64 2.59 0.101865 0 413303 2 select 0.73 0.028817 0 5305207 4105783 getxattr 0.40 0.015848 0 50457 rename 0.38 0.015062 0 4105786 1 stat64 0.22 0.008468 0 600495 openat 0.11 0.004407 0 18630 unlink 0.10 0.003976 0 102520 readlink 0.05 0.002162 0 734747 close 0.03 0.001336 3 523 rmdir 0.01 0.000570 0 48933 chmod 0.01 0.000563 0 50471 utimensat 0.01 0.000314 0 50457 fchmod 0.00 0.000142 0 83786 fstat64 0.00 0.000078 0 5457 brk 0.00 0.000034 3 10 5 waitpid 0.00 0.000026 0 2870 lchown32 0.00 0.000000 0 1 execve 0.00 0.000000 0 2 chdir 0.00 0.000000 0 1 1 access 0.00 0.000000 0 1 kill 0.00 0.000000 0 448 mkdir 0.00 0.000000 0 2 umask 0.00 0.000000 0 2 dup2 0.00 0.000000 0 1 gettimeofday 0.00 0.000000 0 14 symlink 0.00 0.000000 0 550 munmap 0.00 0.000000 0 2 2 sigreturn 0.00 0.000000 0 2 clone 0.00 0.000000 0 7 mprotect 0.00 0.000000 0 12 mremap 0.00 0.000000 0 12 rt_sigaction 0.00 0.000000 0 1 rt_sigprocmask 0.00 0.000000 0 1 getcwd 0.00 0.000000 0 568 mmap2 0.00 0.000000 0 1 geteuid32 0.00 0.000000 0 1 getegid32 0.00 0.000000 0 17 fcntl64 0.00 0.000000 0 1 set_thread_area 0.00 0.000000 0 3 socketpair ------ ----------- ----------- --------- --------- ---------------- 100.00 3.935150 22784374 4759052 total used kernel is 32bit and has PAE enabled Portage 2.2.24 (python 2.7.10-final-0, default/linux/x86/13.0, gcc-4.9.3, glibc-2.21-r1, 3.12.21-jason-bare-i686-1403781919 i686) ================================================================= System uname: Linux-3.12.21-jason-bare-i686-1403781919-i686-Intel-R-_Xeon-R-_CPU_5160_@_3.00GHz-with-gentoo-2.2 KiB Mem: 3374184 total, 164148 free KiB Swap: 0 total, 0 free Timestamp of repository gentoo: Fri, 01 Jan 2016 15:00:01 +0000 sh bash 4.3_p39 ld GNU ld (Gentoo 2.25.1 p1.1) 2.25.1 app-shells/bash: 4.3_p39::gentoo dev-lang/perl: 5.20.2::gentoo dev-lang/python: 2.7.10-r1::gentoo dev-util/cmake: 3.3.1-r1::gentoo dev-util/pkgconfig: 0.28-r2::gentoo sys-apps/baselayout: 2.2::gentoo sys-apps/openrc: 0.18.4::gentoo sys-apps/sandbox: 2.6-r1::gentoo sys-devel/autoconf: 2.69::gentoo sys-devel/automake: 1.11.6-r1::gentoo, 1.13.4::gentoo, 1.15::gentoo sys-devel/binutils: 2.25.1-r1::gentoo sys-devel/gcc: 4.9.3::gentoo sys-devel/gcc-config: 1.7.3::gentoo sys-devel/libtool: 2.4.6::gentoo sys-devel/make: 4.1-r1::gentoo sys-kernel/linux-headers: 3.18::gentoo (virtual/os-headers) sys-libs/glibc: 2.21-r1::gentoo Repositories: gentoo location: /var/db/portage sync-type: rsync sync-uri: rsync://rsync.gentoo.org/gentoo-portage priority: -1000 layer23 location: /dat/local/share/portage masters: gentoo priority: 0 ACCEPT_KEYWORDS="x86" ACCEPT_LICENSE="* -@EULA" CBUILD="i686-pc-linux-gnu" CFLAGS="-O2 -march=i686 -fomit-frame-pointer -pipe" CHOST="i686-pc-linux-gnu" CONFIG_PROTECT="/etc /var/bind" CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/env.d /etc/fonts/fonts.conf /etc/gconf /etc/gentoo-release /etc/php/apache2-php5.6/ext-active/ /etc/php/cgi-php5.6/ext-active/ /etc/php/cli-php5.6/ext-active/ /etc/revdep-rebuild /etc/sandbox.d /etc/terminfo" CXXFLAGS="-O2 -march=i686 -fomit-frame-pointer -pipe" DISTDIR="/tmp" FCFLAGS="-O2 -march=i686 -pipe" FEATURES="assume-digests binpkg-logs config-protect-if-modified distlocks ebuild-locks fixlafiles merge-sync news parallel-fetch preserve-libs protect-owned sandbox sfperms strict unknown-features-warn unmerge-logs unmerge-orphans userfetch userpriv usersandbox usersync" FFLAGS="-O2 -march=i686 -pipe" GENTOO_MIRRORS="http://distfiles.gentoo.org" LANG="C" LC_ALL="de_DE.UTF-8" LDFLAGS="-Wl,-O1 -Wl,--as-needed" MAKEOPTS="-j5" PKGDIR="/tmp" PORTAGE_CONFIGROOT="/" PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --omit-dir-times --compress --force --whole-file --delete --stats --human-readable --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages" PORTAGE_TMPDIR="/var/tmp" USE="acl alsa berkdb bzip2 cli cxx dri fortran gd iconv imap ipv6 jpeg ldap mbox modules mysql ncurses nptl openmp pam pcre perl png readline sasl seccomp session ssl syslog tcpd tiff truetype unicode x86 xml zlib" ABI_X86="32" ALSA_CARDS="ali5451 als4000 atiixp atiixp-modem bt87x ca0106 cmipci emu10k1 emu10k1x ens1370 ens1371 es1938 es1968 fm801 hda-intel intel8x0 intel8x0m maestro3 trident usb-audio via82xx via82xx-modem ymfpci" APACHE2_MODULES="actions alias auth_basic auth_digest filter authn_default authn_file authz_default authz_groupfile authz_host authz_owner authz_user cgi deflate dumpio dav dav_fs dir env expires headers include info log_config mime mime_magic proxy proxy_balancer proxy_connect proxy_http rewrite setenvif so status userdir unique_id vhost_alias" APACHE2_MPMS="itk" CALLIGRA_FEATURES="kexi words flow plan sheets stage tables krita karbon braindump author" CAMERAS="ptp2" COLLECTD_PLUGINS="df interface irq load memory rrdtool swap syslog" ELIBC="glibc" GPSD_PROTOCOLS="ashtech aivdm earthmate evermore fv18 garmin garmintxt gpsclock itrax mtk3301 nmea ntrip navcom oceanserver oldstyle oncore rtcm104v2 rtcm104v3 sirf superstar2 timing tsip tripmate tnt ublox ubx" INPUT_DEVICES="keyboard mouse evdev" KERNEL="linux" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LIBREOFFICE_EXTENSIONS="presenter-console presenter-minimizer" NGINX_MODULES_HTTP="access auth_basic charset dav fastcgi geo gzip limit_req lua map proxy rewrite ssl stub_status" OFFICE_IMPLEMENTATION="libreoffice" PHP_TARGETS="php5-5" PYTHON_SINGLE_TARGET="python_2_7" PYTHON_TARGETS="python2_7" QEMU_SOFTMMU_TARGETS="i386" RUBY_TARGETS="ruby20 ruby21" USERLAND="GNU" VIDEO_CARDS="fbdev glint intel mach64 mga nouveau nv r128 radeon savage sis tdfx trident vesa via vmware dummy v4l" XTABLES_ADDONS="quota2 psd pknock lscan length2 ipv4options ipset ipp2p iface geoip fuzzy condition tee tarpit sysrq steal rawnat logmark ipmark dhcpmac delude chaos account" Unset: CC, CPPFLAGS, CTARGET, CXX, EMERGE_DEFAULT_OPTS, INSTALL_MASK, PORTAGE_BUNZIP2_COMMAND, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS, USE_PYTHON
strace-4.11 is already in the tree ... please test that
same issue using Version 4.11
strace 4.22 has been released recently, and it includes commit v4.21-98-gdfccb60 "Fix -O option handling" that may fix the issue.
yeah, please try 4.22. if that still doesn't work, please file a report upstream here: https://github.com/strace/strace/issues
