diff options
| author | Ömer Sinan Ağacan <omeragacan@gmail.com> | 2016-06-08 09:30:32 -0400 |
|---|---|---|
| committer | Ömer Sinan Ağacan <omeragacan@gmail.com> | 2016-06-08 09:35:41 -0400 |
| commit | d7933cbc28f4f094eba3d128bc147920f68c965b (patch) | |
| tree | 762f62356a9cdab54d2d28ef4d68f8ae2dacbbcb /testsuite/tests/profiling/should_run/prof-doc-last.prof.sample | |
| parent | 80cf4cf0b7ff1513811d985726714c654ef7f032 (diff) | |
| download | haskell-d7933cbc28f4f094eba3d128bc147920f68c965b.tar.gz | |
Show sources of cost centers in .prof
This fixes the problem with duplicate cost-centre names that was
reported a couple of times before. When a module implements a typeclass
multiple times for different types, methods of different implementations
get same cost-centre names and are reported like this:
COST CENTRE MODULE %time %alloc
CAF GHC.IO.Handle.FD 0.0 32.8
CAF GHC.Read 0.0 1.0
CAF GHC.IO.Encoding 0.0 1.8
showsPrec Main 0.0 1.2
readPrec Main 0.0 19.4
readPrec Main 0.0 20.5
main Main 0.0 20.2
individual inherited
COST CENTRE MODULE no. entries %time %alloc %time %alloc
MAIN MAIN 53 0 0.0 0.2 0.0 100.0
CAF Main 105 0 0.0 0.3 0.0 62.5
readPrec Main 109 1 0.0 0.6 0.0 0.6
readPrec Main 107 1 0.0 0.6 0.0 0.6
main Main 106 1 0.0 20.2 0.0 61.0
== Main 114 1 0.0 0.0 0.0 0.0
== Main 113 1 0.0 0.0 0.0 0.0
showsPrec Main 112 2 0.0 1.2 0.0 1.2
showsPrec Main 111 2 0.0 0.9 0.0 0.9
readPrec Main 110 0 0.0 18.8 0.0 18.8
readPrec Main 108 0 0.0 19.9 0.0 19.9
It's not possible to tell from the report which `==` took how long. This
patch adds one more column at the cost of making outputs wider. The
report now looks like this:
COST CENTRE MODULE SRC %time %alloc
CAF GHC.IO.Handle.FD <entire-module> 0.0 32.9
CAF GHC.IO.Encoding <entire-module> 0.0 1.8
CAF GHC.Read <entire-module> 0.0 1.0
showsPrec Main Main_1.hs:7:19-22 0.0 1.2
readPrec Main Main_1.hs:7:13-16 0.0 19.5
readPrec Main Main_1.hs:4:13-16 0.0 20.5
main Main Main_1.hs:(10,1)-(20,20) 0.0 20.2
individual inherited
COST CENTRE MODULE SRC no. entries %time %alloc %time %alloc
MAIN MAIN <built-in> 53 0 0.0 0.2 0.0 100.0
CAF Main <entire-module> 105 0 0.0 0.3 0.0 62.5
readPrec Main Main_1.hs:7:13-16 109 1 0.0 0.6 0.0 0.6
readPrec Main Main_1.hs:4:13-16 107 1 0.0 0.6 0.0 0.6
main Main Main_1.hs:(10,1)-(20,20) 106 1 0.0 20.2 0.0 61.0
== Main Main_1.hs:7:25-26 114 1 0.0 0.0 0.0 0.0
== Main Main_1.hs:4:25-26 113 1 0.0 0.0 0.0 0.0
showsPrec Main Main_1.hs:7:19-22 112 2 0.0 1.2 0.0 1.2
showsPrec Main Main_1.hs:4:19-22 111 2 0.0 0.9 0.0 0.9
readPrec Main Main_1.hs:7:13-16 110 0 0.0 18.8 0.0 18.8
readPrec Main Main_1.hs:4:13-16 108 0 0.0 19.9 0.0 19.9
CAF Text.Read.Lex <entire-module> 102 0 0.0 0.5 0.0 0.5
To fix failing test cases because of different orderings of cost centres
(e.g. optimized and non-optimized build printing in different order),
with this patch we also start sorting cost centres before printing. The
order depends on 1) entries (more entered cost centres come first) 2)
names (using strcmp() on cost centre names).
Reviewers: simonmar, austin, erikd, bgamari
Reviewed By: simonmar, bgamari
Subscribers: thomie
Differential Revision: https://phabricator.haskell.org/D2282
GHC Trac Issues: #11543, #8473, #7105
Diffstat (limited to 'testsuite/tests/profiling/should_run/prof-doc-last.prof.sample')
| -rw-r--r-- | testsuite/tests/profiling/should_run/prof-doc-last.prof.sample | 54 |
1 files changed, 27 insertions, 27 deletions
diff --git a/testsuite/tests/profiling/should_run/prof-doc-last.prof.sample b/testsuite/tests/profiling/should_run/prof-doc-last.prof.sample index dd036490e7..371fad43d7 100644 --- a/testsuite/tests/profiling/should_run/prof-doc-last.prof.sample +++ b/testsuite/tests/profiling/should_run/prof-doc-last.prof.sample @@ -1,34 +1,34 @@ - Thu Apr 2 19:44 2015 Time and Allocation Profiling Report (Final) + Sat Jun 4 11:59 2016 Time and Allocation Profiling Report (Final) - prof-doc-last +RTS -p -RTS + prof-doc-last +RTS -hc -p -RTS - total time = 0.16 secs (160 ticks @ 1000 us, 1 processor) - total alloc = 648,053,608 bytes (excludes profiling overheads) + total time = 0.12 secs (121 ticks @ 1000 us, 1 processor) + total alloc = 384,052,480 bytes (excludes profiling overheads) -COST CENTRE MODULE %time %alloc +COST CENTRE MODULE SRC %time %alloc -last_init_ys Main 28.1 29.6 -main.ys Main 26.2 24.7 -main.xs Main 16.9 12.3 -last_init_xs Main 14.4 14.8 -last_ys Main 7.5 12.3 -last_xs Main 6.9 6.2 +main.ys Main prof-doc-last.hs:3:15-31 39.7 37.5 +last_init_ys Main prof-doc-last.hs:7:45-58 23.1 29.2 +main.xs Main prof-doc-last.hs:2:15-31 23.1 18.7 +last_init_xs Main prof-doc-last.hs:5:46-59 11.6 14.6 +last_xs Main prof-doc-last.hs:4:41-47 1.7 0.0 - individual inherited -COST CENTRE MODULE no. entries %time %alloc %time %alloc + individual inherited +COST CENTRE MODULE SRC no. entries %time %alloc %time %alloc -MAIN MAIN 99 0 0.0 0.0 100.0 100.0 - CAF Main 197 0 0.0 0.0 100.0 100.0 - main Main 198 1 0.0 0.0 100.0 100.0 - last_init_ys Main 204 1 28.1 29.6 28.1 29.6 - main.ys Main 203 1 26.2 24.7 26.2 24.7 - last_ys Main 202 1 7.5 12.3 7.5 12.3 - last_init_xs Main 201 1 14.4 14.8 14.4 14.8 - main.xs Main 200 1 16.9 12.3 16.9 12.3 - last_xs Main 199 1 6.9 6.2 6.9 6.2 - CAF GHC.Conc.Signal 179 0 0.0 0.0 0.0 0.0 - CAF GHC.IO.Encoding 163 0 0.0 0.0 0.0 0.0 - CAF GHC.IO.Encoding.Iconv 161 0 0.0 0.0 0.0 0.0 - CAF GHC.IO.Handle.FD 152 0 0.0 0.0 0.0 0.0 - CAF GHC.IO.Handle.Text 150 0 0.0 0.0 0.0 0.0 +MAIN MAIN <built-in> 46 0 0.0 0.0 100.0 100.0 + CAF Main <entire-module> 91 0 0.0 0.0 0.0 0.0 + main Main prof-doc-last.hs:(2,1)-(7,58) 92 1 0.0 0.0 0.0 0.0 + CAF GHC.IO.Handle.FD <entire-module> 86 0 0.0 0.0 0.0 0.0 + CAF GHC.IO.Handle.Text <entire-module> 85 0 0.0 0.0 0.0 0.0 + CAF GHC.Conc.Signal <entire-module> 81 0 0.0 0.0 0.0 0.0 + CAF GHC.IO.Encoding <entire-module> 78 0 0.0 0.0 0.0 0.0 + CAF GHC.IO.Encoding.Iconv <entire-module> 65 0 0.0 0.0 0.0 0.0 + main Main prof-doc-last.hs:(2,1)-(7,58) 93 0 0.0 0.0 100.0 100.0 + last_init_xs Main prof-doc-last.hs:5:46-59 96 1 11.6 14.6 11.6 14.6 + last_init_ys Main prof-doc-last.hs:7:45-58 99 1 23.1 29.2 23.1 29.2 + last_xs Main prof-doc-last.hs:4:41-47 94 1 1.7 0.0 1.7 0.0 + last_ys Main prof-doc-last.hs:6:41-47 97 1 0.8 0.0 0.8 0.0 + main.xs Main prof-doc-last.hs:2:15-31 95 1 23.1 18.7 23.1 18.7 + main.ys Main prof-doc-last.hs:3:15-31 98 1 39.7 37.5 39.7 37.5 |