[GHC] #8224: Excessive system time -- new IO manager problem?
GHC
ghc-devs at haskell.org
Tue Nov 12 18:57:22 UTC 2013
#8224: Excessive system time -- new IO manager problem?
-------------------------------------+-------------------------------------
Reporter: rrnewton | Owner:
Type: bug | Status: new
Priority: high | Milestone: 7.8.1
Component: Runtime System | Version: 7.7
Resolution: | Keywords: IO Manager,
Operating System: Linux | System Time
Type of failure: Runtime | Architecture: x86_64 (amd64)
performance bug | Difficulty: Unknown
Test Case: | Blocked By:
Blocking: | Related Tickets:
-------------------------------------+-------------------------------------
Comment (by AndreasVoellmy):
Replying to [comment:8 simonmar]:
> 200ms spent doing unspecified "initialization" should definitely be
investigated, that's a lot. I can't see anything useful in that call
stack, it looks like it might be related to signals or epoll() but it's
hard to tell anything else.
>
> What does the `+RTS -s` look like?
With my "one poller" hack:
{{{
48,624 bytes allocated in the heap
40 bytes copied during GC
38,592 bytes maximum residency (1 sample(s))
268,608 bytes maximum slop
32 MB total memory in use (15 MB lost due to fragmentation)
Tot time (elapsed) Avg pause Max
pause
Gen 0 0 colls, 0 par 0.00s 0.00s 0.0000s
0.0000s
Gen 1 1 colls, 0 par 0.00s 0.00s 0.0003s
0.0003s
Parallel GC work balance: -nan (0 / 0, ideal 32)
MUT time (elapsed) GC time (elapsed)
Task 0 (worker) : 0.00s ( 0.00s) 0.00s ( 0.00s)
Task 1 (worker) : 0.00s ( 0.00s) 0.00s ( 0.00s)
Task 2 (bound) : 0.00s ( 0.00s) 0.00s ( 0.00s)
Task 3 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 4 (worker) : 0.02s ( 0.01s) 0.00s ( 0.00s)
Task 5 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 6 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 7 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 8 (worker) : 0.02s ( 0.01s) 0.00s ( 0.00s)
Task 9 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 10 (worker) : 0.02s ( 0.01s) 0.00s ( 0.00s)
Task 11 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 12 (worker) : 0.02s ( 0.01s) 0.00s ( 0.00s)
Task 13 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 14 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 15 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 16 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 17 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 18 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 19 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 20 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 21 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 22 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 23 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 24 (worker) : 0.00s ( 0.01s) 0.00s ( 0.00s)
Task 25 (worker) : 0.00s ( 0.01s) 0.00s ( 0.00s)
Task 26 (worker) : 0.00s ( 0.01s) 0.00s ( 0.00s)
Task 27 (worker) : 0.00s ( 0.01s) 0.00s ( 0.00s)
Task 28 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 29 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 30 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 31 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 32 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
Task 33 (worker) : 0.01s ( 0.01s) 0.00s ( 0.00s)
SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)
INIT time 0.00s ( 0.01s elapsed)
MUT time 0.00s ( 0.00s elapsed)
GC time 0.00s ( 0.00s elapsed)
EXIT time 0.01s ( 0.00s elapsed)
Total time 0.02s ( 0.01s elapsed)
Alloc rate 2,431,200 bytes per MUT second
Productivity 80.0% of total user, 132.3% of total elapsed
gc_alloc_block_sync: 0
whitehole_spin: 0
gen[0].sync: 0
gen[1].sync: 0
}}}
With HEAD:
{{{
543,096 bytes allocated in the heap
64 bytes copied during GC
412,256 bytes maximum residency (1 sample(s))
279,968 bytes maximum slop
18 MB total memory in use (0 MB lost due to fragmentation)
Tot time (elapsed) Avg pause Max
pause
Gen 0 0 colls, 0 par 0.00s 0.00s 0.0000s
0.0000s
Gen 1 1 colls, 0 par 0.00s 0.00s 0.0009s
0.0009s
Parallel GC work balance: -nan% (serial 0%, perfect 100%)
TASKS: 65 (1 bound, 64 peak workers (64 total), using -N32)
SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)
INIT time 0.04s ( 0.03s elapsed)
MUT time 0.00s ( -0.00s elapsed)
GC time 0.00s ( 0.00s elapsed)
EXIT time 0.01s ( 0.00s elapsed)
Total time 0.05s ( 0.04s elapsed)
Alloc rate 0 bytes per MUT second
Productivity 17.4% of total user, 24.7% of total elapsed
gc_alloc_block_sync: 0
whitehole_spin: 0
gen[0].sync: 0
gen[1].sync: 0
}}}
--
Ticket URL: <http://ghc.haskell.org/trac/ghc/ticket/8224#comment:13>
GHC <http://www.haskell.org/ghc/>
The Glasgow Haskell Compiler
More information about the ghc-tickets
mailing list