Log live_bytes and heap_size as reported by GHC.Stats #1508

mpickering · 2021-03-06T16:15:53Z

A thread is spawned which at a prespecified interval will report the
live bytes and heap size at the last major collection.

Live bytes corresponds to how much live data a program has and should
match closely the value reported during heap profiling.

Heap size reports the total amount of memory the RTS is using, which
corresponds more closely to OS memory usage.

[INFO] Live bytes: 367.45MB Heap size: 676.33MB

Closes #1493

ghcide/ghcide.cabal

pepeiborra · 2021-03-06T17:35:37Z

Do either of these values include the bytes allocated in the foreign heap?

pepeiborra · 2021-03-06T17:36:36Z

ghcide/src/Development/IDE/Main/HeapStats.hs

+heapStatsInterval :: Int
+heapStatsInterval = 60_000_000 -- 60s
+


this should be a config option

A command line option? I am not sure configuring this is very useful,

60s seems arbitrary. A config or command line option would make the choice available to the user

pepeiborra · 2021-03-06T17:38:06Z

ghcide/src/Development/IDE/Main/HeapStats.hs

+      format m = T.pack (printf "%.2fMB" (fromIntegral @Word64 @Double m / 1e6))
+      message = "Live bytes: " <> format live_bytes  <> " " <>
+                "Heap size: " <> format heap_size
+  logInfo l message


Is Info the right severity? Telemetry?

I choose Info so that it would show up in any logs that users posted. I can change it to something else if you think it's appropriate (and would show up in logs somewhere under "normal" usage).

I guess it depends what the purpose of this logging is.

mpickering · 2021-03-06T19:01:03Z

Do either of these values include the bytes allocated in the foreign heap?

Do you mean allocations due to mallocBytes? Or by which means exactly? Allocations due to mallocBytes just call malloc so are not tracked by the RTS.

pepeiborra · 2021-03-06T19:16:56Z

Do either of these values include the bytes allocated in the foreign heap?

Do you mean allocations due to mallocBytes? Or by which means exactly? Allocations due to mallocBytes just call malloc so are not tracked by the RTS.

What is the purpose of this logging? If it is to make bug reports then it would be better to show the full RSS or similar, the GHC heap alone is just a fraction of the total memory used by the process

mpickering · 2021-03-06T19:25:36Z

Do you think that a significant amount of RSS for ghcide is off-heap allocations? I would expect the "heap size" number to be quite close to RSS (and this patch would allow people to check easily).

pepeiborra · 2021-03-06T19:50:21Z

Do you think that a significant amount of RSS for ghcide is off-heap allocations? I would expect the "heap size" number to be quite close to RSS (and this patch would allow people to check easily).

Around half and half.

mpickering · 2021-03-06T20:35:39Z

Do you think that a significant amount of RSS for ghcide is off-heap allocations? I would expect the "heap size" number to be quite close to RSS (and this patch would allow people to check easily).

Around half and half.

I just tried loading ghcide into ghcide and then looked at reported VmRSS and how much was heap allocated.

Total VmRSS:   1658008 kB from /proc/pid/status
Heap Rss:         1548084 kB from /proc/pid/smaps in 42000* range

The mem_in_use figure reports "Heap size: 1620.05MB", which is quite close to the /proc/pid/status value.

mpickering · 2021-03-06T20:47:04Z

The numbers I see for my test of loading ghcide into ghcide are:

[INFO] Live bytes: 317.73MB Heap size: 1617.95MB

Which makes sense, as there is 8 * 128mb for the nursery(!) + 317 * 2 for the live data and copying overhead ~1650mb.

If I reenable idle GC then I get probably more accurate numbers

[INFO] Live bytes: 417.13MB Heap size: 1862.27MB

= 128 * 8 + 417*2 = 1858
If I re-enable the idle GC and set -A32M then I get

[INFO] Live bytes: 417.89MB Heap size: 1059.06MB

= 32 * 8 + (4 * 417) ~= 1090

Basically, I think these numbers allow you to work out Rss accurately and the Rss makes sense relative to the live bytes.

pepeiborra · 2021-03-06T21:10:20Z

Does the space used by StringBuffers, FastStrings, ByteStrings and Linkables get included in the "Heap size" number?
Does the Heap size figure stay representative of RSS when multiple components are loaded?

pepeiborra

In any case, there is no reason to not merge this already and it can always be made more accurate later on. Thanks!

mpickering · 2021-03-07T15:01:36Z

Does the space used by StringBuffers, FastStrings, ByteStrings and Linkables get included in the "Heap size" number?
Does the Heap size figure stay representative of RSS when multiple components are loaded?

At least FastString and ByteString are heap allocated (using newByteArray#/newPinnedByteArray#)

mpickering · 2021-03-07T15:01:59Z

Does the space used by StringBuffers, FastStrings, ByteStrings and Linkables get included in the "Heap size" number?
Does the Heap size figure stay representative of RSS when multiple components are loaded?

I didn't test with multiple components but I don't see why it would report incorrect numbers.

mpickering · 2021-03-17T10:08:00Z

Anyone want to merge this?

A thread is spawned which at a prespecified interval will report the live bytes and heap size at the last major collection. Live bytes corresponds to how much live data a program has and should match closely the value reported during heap profiling. Heap size reports the total amount of memory the RTS is using, which corresponds more closely to OS memory usage. ``` [INFO] Live bytes: 367.45MB Heap size: 676.33MB ``` Closes haskell#1493

ghcide/ghcide.cabal

Co-authored-by: Jan Hrcek <[email protected]>

Anton-Latukha · 2021-12-20T02:14:31Z

As #1493 is still open (so still needed) & people proclaimed PR ready & awaiting merge several times, and my additions to it were simple (just a join of IO (IO ...) basically). Merging it on CI success.

Anton-Latukha · 2021-12-20T16:37:37Z

Thanks everybody, especially @mpickering @pepeiborra (& with that sending the additional notice that this statistic is merged).

mpickering force-pushed the wip/heap-stats branch from 09b0657 to a705897 Compare March 6, 2021 16:33

jhrcek reviewed Mar 6, 2021

View reviewed changes

ghcide/ghcide.cabal Outdated Show resolved Hide resolved

pepeiborra reviewed Mar 6, 2021

View reviewed changes

pepeiborra approved these changes Mar 6, 2021

View reviewed changes

This comment has been minimized.

Sign in to view

mpickering force-pushed the wip/heap-stats branch from 463ed1f to c460f78 Compare March 20, 2021 12:03

This comment has been minimized.

Sign in to view

jneira added the merge me Label to trigger pull request merge label Mar 20, 2021

jhrcek reviewed Mar 20, 2021

View reviewed changes

ghcide/ghcide.cabal Outdated Show resolved Hide resolved

pepeiborra and others added 3 commits March 21, 2021 21:00

Merge branch 'master' into wip/heap-stats

e6b973b

Update ghcide/ghcide.cabal

adcd0fd

Co-authored-by: Jan Hrcek <[email protected]>

Merge branch 'master' into wip/heap-stats

74cb490

This comment has been minimized.

Sign in to view

Merge branch 'master' into wip/heap-stats

cb8ba71

Ailrun added the status: needs attention label Apr 4, 2021

This comment has been minimized.

Sign in to view

jneira removed the status: needs attention label Apr 26, 2021

jneira added the pr: needs rebase label Apr 26, 2021

jneira removed the merge me Label to trigger pull request merge label May 31, 2021

Anton-Latukha mentioned this pull request Dec 20, 2021

testing PR #1508 rebase #2512

Closed

This comment has been minimized.

Sign in to view

Merge branch 'master' into wip/heap-stats

63eadb5

This comment has been minimized.

Sign in to view

Anton-Latukha added merge me Label to trigger pull request merge and removed pr: needs rebase labels Dec 20, 2021

mergify bot merged commit e1949dd into haskell:master Dec 20, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log live_bytes and heap_size as reported by GHC.Stats #1508

Log live_bytes and heap_size as reported by GHC.Stats #1508

mpickering commented Mar 6, 2021 •

edited by gitpod-io bot

Loading

pepeiborra commented Mar 6, 2021

pepeiborra Mar 6, 2021

mpickering Mar 6, 2021

pepeiborra Mar 6, 2021

pepeiborra Mar 6, 2021

mpickering Mar 6, 2021

pepeiborra Mar 6, 2021

mpickering commented Mar 6, 2021

pepeiborra commented Mar 6, 2021

mpickering commented Mar 6, 2021

pepeiborra commented Mar 6, 2021

mpickering commented Mar 6, 2021

mpickering commented Mar 6, 2021

pepeiborra commented Mar 6, 2021

pepeiborra left a comment

mpickering commented Mar 7, 2021

mpickering commented Mar 7, 2021

mpickering commented Mar 17, 2021

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

Anton-Latukha commented Dec 20, 2021 •

edited

Loading

Anton-Latukha commented Dec 20, 2021 •

edited

Loading

		heapStatsInterval :: Int
		heapStatsInterval = 60_000_000 -- 60s

Log live_bytes and heap_size as reported by GHC.Stats #1508

Log live_bytes and heap_size as reported by GHC.Stats #1508

Conversation

mpickering commented Mar 6, 2021 • edited by gitpod-io bot Loading

pepeiborra commented Mar 6, 2021

pepeiborra Mar 6, 2021

Choose a reason for hiding this comment

mpickering Mar 6, 2021

Choose a reason for hiding this comment

pepeiborra Mar 6, 2021

Choose a reason for hiding this comment

pepeiborra Mar 6, 2021

Choose a reason for hiding this comment

mpickering Mar 6, 2021

Choose a reason for hiding this comment

pepeiborra Mar 6, 2021

Choose a reason for hiding this comment

mpickering commented Mar 6, 2021

pepeiborra commented Mar 6, 2021

mpickering commented Mar 6, 2021

pepeiborra commented Mar 6, 2021

mpickering commented Mar 6, 2021

mpickering commented Mar 6, 2021

pepeiborra commented Mar 6, 2021

pepeiborra left a comment

Choose a reason for hiding this comment

mpickering commented Mar 7, 2021

mpickering commented Mar 7, 2021

mpickering commented Mar 17, 2021

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

Anton-Latukha commented Dec 20, 2021 • edited Loading

Anton-Latukha commented Dec 20, 2021 • edited Loading

mpickering commented Mar 6, 2021 •

edited by gitpod-io bot

Loading

Anton-Latukha commented Dec 20, 2021 •

edited

Loading

Anton-Latukha commented Dec 20, 2021 •

edited

Loading