[GHC] #13492: -p option report much less time than actual on high intensity of FFI calls application
#13492: -p option report much less time than actual on high intensity of FFI calls application -------------------------------------+------------------------------------- Reporter: varosi | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Profiling | Version: 8.0.2 Keywords: | Operating System: Windows Architecture: x86_64 | Type of failure: Debugging (amd64) | information is incorrect Test Case: | Blocked By: Blocking: | Related Tickets: Differential Rev(s): | Wiki Page: -------------------------------------+------------------------------------- Proprietary application is ran on 44 cores (88 with HT) machine (same problem on 12 core). It is Haskell between wxHaskell (wxWidgets for UI) and C API. It is doing FFI calls most of the time. Calls are not so many, but possibly not so fast. I'm trying to profile where is the problem, in which calls. But very strange behaviour is there. "total time" of application that is running 30secs to 1min is showing 0.33secs. Even MAIN function is not 100%. Please, see first part of .prof file: Tue Mar 28 15:38 2017 Time and Allocation Profiling Report (Final) app.exe +RTS -N -A40m -qb0 -p -RTS total time = 0.33 secs (325 ticks @ 1000 us, 1 processor) total alloc = 86,317,264 bytes (excludes profiling overheads) COST CENTRE MODULE SRC %time %alloc MAIN MAIN <built- in> 12.6 2.2 -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/13492 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#13492: -p option report much less time than actual on high intensity of FFI calls application -------------------------------------+------------------------------------- Reporter: varosi | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Profiling | Version: 8.0.2 Resolution: | Keywords: Operating System: Windows | Architecture: x86_64 Type of failure: Debugging | (amd64) information is incorrect | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): The cost-center profiler only measures the time spent in the mutator (that is, actually doing Haskell evaluation). It will not report time spent in FFI calls. For that you will need to use your platform's native profiler. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/13492#comment:1 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#13492: -p option report much less time than actual on high intensity of FFI calls application -------------------------------------+------------------------------------- Reporter: varosi | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Profiling | Version: 8.0.2 Resolution: | Keywords: Operating System: Windows | Architecture: x86_64 Type of failure: Debugging | (amd64) information is incorrect | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by varosi): It'll be great if there is some statistic that include FFI calls and give some FFI statistics, too. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/13492#comment:2 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#13492: -p option report much less time than actual on high intensity of FFI calls application -------------------------------------+------------------------------------- Reporter: varosi | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Profiling | Version: 8.5 Resolution: | Keywords: Operating System: Windows | Architecture: x86_64 Type of failure: Debugging | (amd64) information is incorrect | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by osa1): * cc: simonmar, osa1 (added) * version: 8.0.2 => 8.5 Comment: I recently needed this and ended up using event logs as profiler did not help because of this issue. Unfortunately event logs also have its problems (e.g. can't load events for a few minutes because ghc-events requires more than 32G RAM for that...), so this feature would still be useful. See also the recent Haskell-cafe questions on this [https://mail.haskell.org/pipermail/haskell-cafe/2018-August/129818.html here] and my response [https://mail.haskell.org/pipermail/haskell- cafe/2018-August/129820.html here]. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/13492#comment:3 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#13492: -p option report much less time than actual on high intensity of FFI calls application -------------------------------------+------------------------------------- Reporter: varosi | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Profiling | Version: 8.5 Resolution: | Keywords: Operating System: Windows | Architecture: x86_64 Type of failure: Debugging | (amd64) information is incorrect | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by j.waldmann): I want this. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/13492#comment:4 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#13492: -p option report much less time than actual on high intensity of FFI calls application -------------------------------------+------------------------------------- Reporter: varosi | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Profiling | Version: 8.5 Resolution: | Keywords: Operating System: Windows | Architecture: x86_64 Type of failure: Debugging | (amd64) information is incorrect | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): I agree that our eventlog tooling has significant weaknesses. Using O(n) memory in a trace analysis tool is quite problematic. Ultimately I would actually like to see the eventlog supercede our ad-hoc `hp` (and perhaps some day `prof`) format for profiling but these issues will first need to be resolved. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/13492#comment:5 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#13492: -p option report much less time than actual on high intensity of FFI calls application -------------------------------------+------------------------------------- Reporter: varosi | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Profiling | Version: 8.5 Resolution: | Keywords: Operating System: Windows | Architecture: x86_64 Type of failure: Debugging | (amd64) information is incorrect | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by maoe): * cc: maoe (added) -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/13492#comment:6 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#13492: -p option report much less time than actual on high intensity of FFI calls application -------------------------------------+------------------------------------- Reporter: varosi | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Profiling | Version: 8.5 Resolution: | Keywords: Operating System: Windows | Architecture: x86_64 Type of failure: Debugging | (amd64) information is incorrect | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by adamse): * cc: adamse (added) -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/13492#comment:7 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
participants (1)
-
GHC