GHC 8.2 GC time stats going negative

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

GHC 8.2 GC time stats going negative

Harendra Kumar
Hi,

I am trying to use the mutator_cpu_ns and mutator_elapsed_ns from GHC 8.2 RTSStats structure retrieved using getRTSStats API documented here - https://hackage.haskell.org/package/base-4.10.0.0/docs/GHC-Stats.html .

I am seeing that the values of these stats retrieved about 30 ms later are lower than the values retrieved earlier. Sometimes even after 100 ms the values decrease from the previous ones. However, as the time duration between two calls increase this becomes less and less likely.

Is this an expected behavior or am I using it incorrectly? If it is expected, why does it happen, what is the underlying mechanism that makes it happen? 

Thanks,
harendra

_______________________________________________
ghc-devs mailing list
[hidden email]
http://mail.haskell.org/cgi-bin/mailman/listinfo/ghc-devs
Reply | Threaded
Open this post in threaded view
|

Re: GHC 8.2 GC time stats going negative

Ben Gamari-3
Harendra Kumar <[hidden email]> writes:

> Hi,
>
> I am trying to use the mutator_cpu_ns and mutator_elapsed_ns from GHC 8.2
> RTSStats structure retrieved using getRTSStats API documented here -
> https://hackage.haskell.org/package/base-4.10.0.0/docs/GHC-Stats.html .
>
> I am seeing that the values of these stats retrieved about 30 ms later are
> lower than the values retrieved earlier. Sometimes even after 100 ms the
> values decrease from the previous ones. However, as the time duration
> between two calls increase this becomes less and less likely.
>
> Is this an expected behavior or am I using it incorrectly? If it is
> expected, why does it happen, what is the underlying mechanism that makes
> it happen?
>
Hmm, interesting. I don't believe this should happen and I do know of
bugs in the RTS's time accounting at exit-time (manifesting in profiling
issues, e.g. #14257) however what you describe doesn't seem to fit that
description. Do you have a simple repro? Is there anything special about
your program (e.g. lots of FFI calls)?

Cheers,

- Ben

_______________________________________________
ghc-devs mailing list
[hidden email]
http://mail.haskell.org/cgi-bin/mailman/listinfo/ghc-devs

signature.asc (497 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: GHC 8.2 GC time stats going negative

Harendra Kumar
Hi Ben,

Yes, there are FFI calls between the two getRTSStats calls. FFI calls are C APIs to get some OS stats like clock time or cpu time etc. Now I know that this is not expected, let me try to minimize the example and see where it goes. I will try removing the FFI calls as well.

-harendra

On 9 November 2017 at 23:49, Ben Gamari <[hidden email]> wrote:
Harendra Kumar <[hidden email]> writes:

> Hi,
>
> I am trying to use the mutator_cpu_ns and mutator_elapsed_ns from GHC 8.2
> RTSStats structure retrieved using getRTSStats API documented here -
> https://hackage.haskell.org/package/base-4.10.0.0/docs/GHC-Stats.html .
>
> I am seeing that the values of these stats retrieved about 30 ms later are
> lower than the values retrieved earlier. Sometimes even after 100 ms the
> values decrease from the previous ones. However, as the time duration
> between two calls increase this becomes less and less likely.
>
> Is this an expected behavior or am I using it incorrectly? If it is
> expected, why does it happen, what is the underlying mechanism that makes
> it happen?
>
Hmm, interesting. I don't believe this should happen and I do know of
bugs in the RTS's time accounting at exit-time (manifesting in profiling
issues, e.g. #14257) however what you describe doesn't seem to fit that
description. Do you have a simple repro? Is there anything special about
your program (e.g. lots of FFI calls)?

Cheers,

- Ben


_______________________________________________
ghc-devs mailing list
[hidden email]
http://mail.haskell.org/cgi-bin/mailman/listinfo/ghc-devs
Reply | Threaded
Open this post in threaded view
|

Re: GHC 8.2 GC time stats going negative

Harendra Kumar
Ben,

I could reproduce it even after removing all FFI calls. I created a ghc trac ticket, you can find it here: https://ghc.haskell.org/trac/ghc/ticket/14445. Let me know if any more information is needed or if explanation about the code/repo is required.

Thanks,
Harendra


On 10 November 2017 at 00:12, Harendra Kumar <[hidden email]> wrote:
Hi Ben,

Yes, there are FFI calls between the two getRTSStats calls. FFI calls are C APIs to get some OS stats like clock time or cpu time etc. Now I know that this is not expected, let me try to minimize the example and see where it goes. I will try removing the FFI calls as well.

-harendra

On 9 November 2017 at 23:49, Ben Gamari <[hidden email]> wrote:
Harendra Kumar <[hidden email]> writes:

> Hi,
>
> I am trying to use the mutator_cpu_ns and mutator_elapsed_ns from GHC 8.2
> RTSStats structure retrieved using getRTSStats API documented here -
> https://hackage.haskell.org/package/base-4.10.0.0/docs/GHC-Stats.html .
>
> I am seeing that the values of these stats retrieved about 30 ms later are
> lower than the values retrieved earlier. Sometimes even after 100 ms the
> values decrease from the previous ones. However, as the time duration
> between two calls increase this becomes less and less likely.
>
> Is this an expected behavior or am I using it incorrectly? If it is
> expected, why does it happen, what is the underlying mechanism that makes
> it happen?
>
Hmm, interesting. I don't believe this should happen and I do know of
bugs in the RTS's time accounting at exit-time (manifesting in profiling
issues, e.g. #14257) however what you describe doesn't seem to fit that
description. Do you have a simple repro? Is there anything special about
your program (e.g. lots of FFI calls)?

Cheers,

- Ben



_______________________________________________
ghc-devs mailing list
[hidden email]
http://mail.haskell.org/cgi-bin/mailman/listinfo/ghc-devs