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

[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

[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

[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