multi-second application stall in open()

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]


I am trying to diagnose a stall in an application when making a call
to open() with O_TRUNC. The issue was originally seen on 2.6.38 and
I've since reproduced on 2.6.35. I believe the last kernel that I did
not see the stall was 2.6.32. The system is under low to moderate cpu
and memory load when the issue occurs. The filesystem is ext2, but I
mounted it as ext4 and still saw the issue.

To me it appears the O_TRUNC needs to truncate pages in the page
cache, but maybe those are already out for writeback? This causes the
open() to wait until that operation completes at which time it is then
able to proceed. If that's true then it looks like the writeback is
sitting on the queue forever waiting (tens of seconds) to be
dispatched to the device.

Here's some more info/data I collected:
(Unfortunately the data here and attached are from separate runs so
the #s will not match up file to file.)

Snippet of an strace when it is hanging:
1329323286.589182 close(37)             = 0 <0.000010>
1329323286.589212 clock_gettime(0x5 /* CLOCK_??? */, {1329323286,
587579583}) = 0 <0.000007>
1329323286.589241 open("/usr/local/etc/abcd/known/test808",
O_WRONLY|O_CREAT|O_TRUNC, 0644)                = 37 <76.841586>
1329323363.441841 fchmod(37, 0644)      = 0 <0.000012>
1329323363.441882 fcntl64(37, F_GETFL)  = 0x1 (flags O_WRONLY) <0.000011>
1329323363.441915 fcntl64(37, F_SETFL, O_WRONLY|O_NONBLOCK) = 0 <0.000010>

To debug this more I enabled the hang check timer to dump stack when
anything hung for longer than 10s. There I see the the hanging
application appearing to be stuck in sync_page(). See attached dmesg
for traces.

I've also captured "iostat -xm 1" while the application was running
and have attached a snippet of that when the problem is occurring. I
see 100% utilization for many seconds and then eventually the
operations complete, but the await time is extremely high. To me there
doesn't look like much IO going on which could be starving out any
requests.

I have not been able to perform a full bisection to better understand
what may be causing this, but do see this on 2.6.38, a little less
frequently but still occurs on 2.6.35, and no longer see the issue on
2.6.32. If I switch slice_idle to 0 or change to the deadline
scheduler the issue appears to go away in both 2.6.35 and 38.

I've also attached the "blkparse -t" output a few seconds before and
after the issue occurs, and the avg file from the output of "btt -i
... -o bp.log"

Please let me know if any other data would be helpful.
I would appreciate any help in better understanding this issue and
what may be causing it.

-- 
Josh

Attachment: blktrace.sda.out
Description: Binary data

Attachment: bp.log.avg
Description: Binary data

Attachment: dmesg
Description: Binary data

Attachment: iostat.out
Description: Binary data


[Other Archives]     [Linux Kernel Newbies]     [Linux Driver Development]     [Fedora Kernel]     [Linux Kernel Testers]     [Linux SH]     [Linux Omap]     [Linux Kbuild]     [Linux Tape]     [Linux Input]     [Linux Kernel Janitors]     [Linux Kernel Packagers]     [Linux Doc]     [Linux Man Pages]     [Linux API]     [Linux Memory Management]     [Linux Modules]     [Linux Standards]     [Kernel Announce]     [Netdev]     [Git]     [Linux PCI]     Linux CAN Development     [Linux I2C]     [Linux RDMA]     [Linux NUMA]     [Netfilter]     [Netfilter Devel]     [SELinux]     [Bugtraq]     [FIO]     [Linux Perf Users]     [Linux Serial]     [Linux PPP]     [Linux ISDN]     [Linux Next]     [Kernel Stable Commits]     [Linux Tip Commits]     [Kernel MM Commits]     [Linux Security Module]     [Filesystem Development]     [Ext3 Filesystem]     [Linux bcache]     [Ext4 Filesystem]     [Linux BTRFS]     [Linux CEPH Filesystem]     [Linux XFS]     [XFS]     [Linux NFS]     [Linux CIFS]     [Ecryptfs]     [Linux NILFS]     [Linux Cachefs]     [Reiser FS]     [Initramfs]     [Linux FB Devel]     [Linux OpenGL]     [DRI Devel]     [Fastboot]     [Linux RT Users]     [Linux RT Stable]     [eCos]     [Corosync]     [Linux Clusters]     [LVS Devel]     [Hot Plug]     [Linux Virtualization]     [KVM]     [KVM PPC]     [KVM ia64]     [Linux Containers]     [Linux Hexagon]     [Linux Cgroups]     [Util Linux]     [Wireless]     [Linux Bluetooth]     [Bluez Devel]     [Ethernet Bridging]     [Embedded Linux]     [Barebox]     [Linux MMC]     [Linux IIO]     [Sparse]     [Smatch]     [Linux Arch]     [x86 Platform Driver]     [Linux ACPI]     [Linux IBM ACPI]     [LM Sensors]     [CPU Freq]     [Linux Power Management]     [Linmodems]     [Linux DCCP]     [Linux SCTP]     [ALSA Devel]     [Linux USB]     [Linux PA RISC]     [Linux Samsung SOC]     [MIPS Linux]     [IBM S/390 Linux]     [ARM Linux]     [ARM Kernel]     [ARM MSM]     [Tegra Devel]     [Sparc Linux]     [Linux Security]     [Linux Sound]     [Linux Media]     [Video 4 Linux]     [Linux IRDA Users]     [Linux for the blind]     [Linux RAID]     [Linux ATA RAID]     [Device Mapper]     [Linux SCSI]     [SCSI Target Devel]     [Linux SCSI Target Infrastructure]     [Linux IDE]     [Linux SMP]     [Linux AXP]     [Linux Alpha]     [Linux M68K]     [Linux ia64]     [Linux 8086]     [Linux x86_64]     [Linux Config]     [Linux Apps]     [Linux MSDOS]     [Linux X.25]     [Linux Crypto]     [DM Crypt]     [Linux Trace Users]     [Linux Btrace]     [Linux Watchdog]     [Utrace Devel]     [Linux C Programming]     [Linux Assembly]     [Dash]     [DWARVES]     [Hail Devel]     [Linux Kernel Debugger]     [Linux gcc]     [Gcc Help]     [X.Org]     [Wine]

Add to Google Powered by Linux

[Older Kernel Discussion]     [Yosemite National Park Forum]     [Large Format Photos]     [Gimp]     [Yosemite Photos]     [Stuff]