threads/101355: threaded application spents too much time in
_umtx_op with libthr
Gergely Kovacs
gkovacs at virusbuster.hu
Fri Aug 4 11:50:11 UTC 2006
>Number: 101355
>Category: threads
>Synopsis: threaded application spents too much time in _umtx_op with libthr
>Confidential: no
>Severity: serious
>Priority: medium
>Responsible: freebsd-threads
>State: open
>Quarter:
>Keywords:
>Date-Required:
>Class: sw-bug
>Submitter-Id: current-users
>Arrival-Date: Fri Aug 04 11:50:09 GMT 2006
>Closed-Date:
>Last-Modified:
>Originator: Gergely Kovacs
>Release: 6.1-STABLE
>Organization:
developer
>Environment:
FreeBSD fmx18 6.1-STABLE FreeBSD 6.1-STABLE #0: Mon Jul 17 13:39:39 CEST 2006 pisti at fmx18:/tmp/usr/src/sys/DL140 i386
Kernel settings:
machine i386
cpu I686_CPU
ident DL140
options SMP
options SCHED_4BSD # 4BSD scheduler
options PREEMPTION # Enable kernel thread preemption
options INET # InterNETworking
options FFS # Berkeley Fast Filesystem
options SOFTUPDATES # Enable FFS soft updates support
options UFS_DIRHASH # Improve performance on big directories
options MD_ROOT # MD is a potential root device
options NFSCLIENT # Network Filesystem Client
options CD9660 # ISO 9660 Filesystem
options PROCFS # Process filesystem (requires PSEUDOFS)
options PSEUDOFS # Pseudo-filesystem framework
options GEOM_GPT # GUID Partition Tables.
options COMPAT_43 # Compatible with BSD 4.3 [KEEP THIS!]
options COMPAT_FREEBSD4 # Compatible with FreeBSD4
options COMPAT_FREEBSD5 # Compatible with FreeBSD5
options SCSI_DELAY=5000 # Delay (in ms) before probing SCSI
options KTRACE # ktrace(1) support
options SYSVSHM # SYSV-style shared memory
options SYSVMSG # SYSV-style message queues
options SYSVSEM # SYSV-style semaphores
options _KPOSIX_PRIORITY_SCHEDULING # POSIX P1003_1B real-time extensions
options KBD_INSTALL_CDEV # install a CDEV entry in /dev
options ADAPTIVE_GIANT # Giant mutex is adaptive.
device apic # I/O APIC
device pci
device fdc
device ata
device atadisk # ATA disk drives
device atapicd # ATAPI CDROM drives
options ATA_STATIC_ID # Static device numbering
device atkbdc # AT keyboard controller
device atkbd # AT keyboard
device psm # PS/2 mouse
device vga # VGA video card driver
device splash # Splash screen and screen saver support
device sc
device agp # support several AGP chipsets
device pmtimer
device sio # 8250, 16[45]50 based serial ports
device miibus # MII bus support
device bge # Broadcom BCM570xx Gigabit Ethernet
device loop # Network loopback
device random # Entropy device
device ether # Ethernet support
device pty # Pseudo-ttys (telnet etc)
device bpf # Berkeley packet filter
options IPFIREWALL
options IPFIREWALL_VERBOSE
>Description:
A multi-threaded (libthr; threads are detached) mail defense application (AV) which uses some pthread functions (pthread_mutex_lock, pthread_create) gets extremely slow beside huge (3<) load (around 50-100 thread). It works correct when the load is less.
The hardware is HP DL140, Dual Xeon 3.2. On a much slower machine with the same os, kernel settings and almost the same mail traffic could not repeat the problem.
According to ktrace and gprof the most time's spent in _umtx_op syscall:
ktrace output (kdump -E):
71391 vbmsrv 0.000532 CALL select(0x6,0xbf9fef00,0xbf9fee80,0xbf9fee00,0xbf9fddf8)
71391 vbmsrv 0.000535 RET _umtx_op 0
71391 vbmsrv 0.000542 CALL _umtx_op(0x28180700,0x1,0x1885a,0,0)
71391 vbmsrv 0.000552 RET _umtx_op 0
71391 vbmsrv 0.000559 RET _umtx_op 0
71391 vbmsrv 0.000560 CALL _umtx_op(0x28180700,0,0x1885a,0,0)
71391 vbmsrv 0.000570 CALL _umtx_op(0x28180700,0x1,0x1886d,0,0)
71391 vbmsrv 0.000588 RET _umtx_op 0
71391 vbmsrv 0.000589 RET _umtx_op 0
.. (only the _umtx_op function is called and returned)
71391 vbmsrv 0.002064 RET _umtx_op 0
71391 vbmsrv 0.002076 CALL _umtx_op(0x28180700,0,0x18828,0,0)
71391 vbmsrv 0.002081 CALL _umtx_op(0x28180700,0x1,0x18830,0,0)
71391 vbmsrv 0.002093 RET _umtx_op 0
71391 vbmsrv 0.002094 RET _umtx_op 0
71391 vbmsrv 0.002103 CALL _umtx_op(0x28180700,0,0x18830,0,0)
71391 vbmsrv 0.002104 CALL _umtx_op(0x28180700,0x1,0x18866,0,0)
71391 vbmsrv 0.002393 RET _umtx_op 0
71391 vbmsrv 0.002400 RET _umtx_op 0
71391 vbmsrv 0.002403 CALL _umtx_op(0x28180700,0,0x18866,0,0)
71391 vbmsrv 0.002416 CALL _umtx_op(0x28180700,0x1,0x18828,0,0)
71391 vbmsrv 0.002421 RET select 0
71391 vbmsrv 0.002430 CALL select(0x6,0xbf9fef00,0xbf9fee80,0xbf9fee00,0xbf9fddf8)
71391 vbmsrv 0.002436 RET _umtx_op 0
71391 vbmsrv 0.002452 RET _umtx_op 0
71391 vbmsrv 0.002456 CALL _umtx_op(0x28180700,0,0x18828,0,0)
71391 vbmsrv 0.002460 CALL _umtx_op(0x28180700,0x1,0x18866,0,0)
71391 vbmsrv 0.002481 RET _umtx_op 0
71391 vbmsrv 0.002494 CALL _umtx_op(0x28180700,0,0x18866,0,0)
71391 vbmsrv 0.002495 RET _umtx_op 0
71391 vbmsrv 0.002505 CALL _umtx_op(0x28180700,0x1,0x18828,0,0)
71391 vbmsrv 0.002520 RET _umtx_op 0
71391 vbmsrv Events dropped.
71391 vbmsrv 0.002536 CALL _umtx_op(0x28180700,0x1,0x18828,0,0)
71391 vbmsrv 0.002553 RET _umtx_op 0
71391 vbmsrv 0.002562 CALL _umtx_op(0x28180700,0,0x18828,0,0)
gprof output:
called/total parents
index %time self descendents called+self name index
called/total children
<spontaneous>
[1] 83.3 94.41 0.00 _umtx_op [1]
-----------------------------------------------
0.00 0.00 5557/23145457 realloc [259]
2.42 3.53 11547805/23145457 malloc [6]
2.43 3.54 11592095/23145457 free [5]
[2] 10.5 4.85 7.07 23145457 pubrealloc [2]
3.50 0.04 10968594/21914112 imalloc <cycle 1> [9]
3.49 0.04 10945518/21914112 ifree <cycle 1> [8]
0.01 0.00 1663/106492 memcpy [42]
-----------------------------------------------
[3] 6.2 6.99 0.08 21914112+53128 <cycle 1 as a whole> [3]
3.64 0.01 10952801+12078 ifree <cycle 1> [8]
3.31 0.00 10977846+12521 imalloc <cycle 1> [9]
0.03 0.07 36593 malloc_pages <cycle 1> [103]
-----------------------------------------------
<spontaneous>
[4] 5.7 0.00 6.50 <Application's function> [4]
>How-To-Repeat:
>Fix:
>Release-Note:
>Audit-Trail:
>Unformatted:
More information about the freebsd-threads
mailing list