bokeh server logs: uncollected Documents?

Hi everyone,

We started a bokeh server with the option --stats-log-frequency to see additional logging.

We are serving a bokeh app continuously: when the websocket is closed, the session is ‘discarded’ and then the document modules are deleted. However the bokeh server logs show output like:

2018-05-09 10:49:37,922 INFO: WebSocket connection closed: code=1001, reason=None

2018-05-09 10:49:44,768 DEBUG: Scheduling 1 sessions to discard

2018-05-09 10:49:44,768 DEBUG: Discarding session ‘73baecb12ac25adaa492f3af6f260551dd10c38d5f97b453c2eadecd047aa463’ last in use 6845.971878007054 milliseconds ago

2018-05-09 10:49:44,768 DEBUG: Deleting 1 modules for <bokeh.document.document.Document object at 0x7fc0dc73b7b8>

2018-05-09 10:49:47,234 DEBUG: Sending options message heartbeat on idle connection (140466362888032) 172.17.0.2

2018-05-09 10:49:47,235 DEBUG: Sending options message heartbeat on idle connection (140466362887416) 172.17.0.2

2018-05-09 10:49:47,235 DEBUG: Received options response on connection (140466362887416) from 172.17.0.2

2018-05-09 10:49:47,236 DEBUG: Received options response on connection (140466362888032) from 172.17.0.2

2018-05-09 10:49:59,767 DEBUG: [pid 62674] 0 clients connected

2018-05-09 10:49:59,767 DEBUG: [pid 62674] /bokeh_server has 0 sessions with 0 unused

2018-05-09 10:49:59,768 INFO: [pid 62674] Memory usage: 176.00 MB (RSS), 1159.00 MB (VMS)

2018-05-09 10:49:59,795 DEBUG: uncollected Documents: 2

2018-05-09 10:49:59,823 DEBUG: uncollected Sessions: 0

2018-05-09 10:49:59,865 DEBUG: uncollected Models: 0

What are these uncollected Documents? How can we delete them? They seem to always exist.

Thanks!

Corey

Okay it seems this may be related to the memory leak in the Bokeh server. Bryan introduced the new logging here: https://github.com/bokeh/bokeh/pull/7604/files

These uncollected Documents are objects that GC hasn’t collected yet…and never does even though our ‘app’ is running in the server but no user is using a browser at all.

Okay, so I think the way to maybe fix this is to use the lifecycle hook to use the new ‘destroy’ Document method introduced in the above PR since that also calls GC directly after deleting the document.

Will update on Monday.

···

On Wednesday, May 9, 2018 at 1:22:08 PM UTC+2, omearac wrote:

Hi everyone,

We started a bokeh server with the option --stats-log-frequency to see additional logging.

We are serving a bokeh app continuously: when the websocket is closed, the session is ‘discarded’ and then the document modules are deleted. However the bokeh server logs show output like:

2018-05-09 10:49:37,922 INFO: WebSocket connection closed: code=1001, reason=None

2018-05-09 10:49:44,768 DEBUG: Scheduling 1 sessions to discard

2018-05-09 10:49:44,768 DEBUG: Discarding session ‘73baecb12ac25adaa492f3af6f260551dd10c38d5f97b453c2eadecd047aa463’ last in use 6845.971878007054 milliseconds ago

2018-05-09 10:49:44,768 DEBUG: Deleting 1 modules for <bokeh.document.document.Document object at 0x7fc0dc73b7b8>

2018-05-09 10:49:47,234 DEBUG: Sending options message heartbeat on idle connection (140466362888032) 172.17.0.2

2018-05-09 10:49:47,235 DEBUG: Sending options message heartbeat on idle connection (140466362887416) 172.17.0.2

2018-05-09 10:49:47,235 DEBUG: Received options response on connection (140466362887416) from 172.17.0.2

2018-05-09 10:49:47,236 DEBUG: Received options response on connection (140466362888032) from 172.17.0.2

2018-05-09 10:49:59,767 DEBUG: [pid 62674] 0 clients connected

2018-05-09 10:49:59,767 DEBUG: [pid 62674] /bokeh_server has 0 sessions with 0 unused

2018-05-09 10:49:59,768 INFO: [pid 62674] Memory usage: 176.00 MB (RSS), 1159.00 MB (VMS)

2018-05-09 10:49:59,795 DEBUG: uncollected Documents: 2

2018-05-09 10:49:59,823 DEBUG: uncollected Sessions: 0

2018-05-09 10:49:59,865 DEBUG: uncollected Models: 0

What are these uncollected Documents? How can we delete them? They seem to always exist.

Thanks!

Corey

Hi,

To investigate in detail, we really need instructions (and code) to reproduce. I will say that an empty document with no models (which seems to be the case, as there are 0 uncollected models) should should take up perhaps hundred of bytes. Which isn't to say it should't be investigated, but previously entire arbitrarily large CDS structures or modules with large data frames could stick around, leaking MBs of GBs. What is the rate of increase of uncollected documents? Is there an increase over time at all? There may be a small number created that are simply overhead and will never go away, but that show up in that report because the scan is very coarse and does not consider whether the documents are internal overhead or were created to service a session. If the number is not increasing then it can be safely ignored.

Thanks,

Bryan

···

On May 10, 2018, at 22:37, 'omearac' via Bokeh Discussion - Public <[email protected]> wrote:

Okay it seems this may be related to the memory leak in the Bokeh server. Bryan introduced the new logging here: https://github.com/bokeh/bokeh/pull/7604/files

These uncollected Documents are objects that GC hasn't collected yet...and never does even though our 'app' is running in the server but no user is using a browser at all.

Okay, so I think the way to maybe fix this is to use the lifecycle hook to use the new 'destroy' Document method introduced in the above PR since that also calls GC directly after deleting the document.

Will update on Monday.

On Wednesday, May 9, 2018 at 1:22:08 PM UTC+2, omearac wrote:
Hi everyone,

We started a bokeh server with the option --stats-log-frequency to see additional logging.

We are serving a bokeh app continuously: when the websocket is closed, the session is 'discarded' and then the document modules are deleted. However the bokeh server logs show output like:

2018-05-09 10:49:37,922 INFO: WebSocket connection closed: code=1001, reason=None
2018-05-09 10:49:44,768 DEBUG: Scheduling 1 sessions to discard
2018-05-09 10:49:44,768 DEBUG: Discarding session '73baecb12ac25adaa492f3af6f260551dd10c38d5f97b453c2eadecd047aa463' last in use 6845.971878007054 milliseconds ago
2018-05-09 10:49:44,768 DEBUG: Deleting 1 modules for <bokeh.document.document.Document object at 0x7fc0dc73b7b8>
2018-05-09 10:49:47,234 DEBUG: Sending options message heartbeat on idle connection (140466362888032) 172.17.0.2
2018-05-09 10:49:47,235 DEBUG: Sending options message heartbeat on idle connection (140466362887416) 172.17.0.2
2018-05-09 10:49:47,235 DEBUG: Received options response on connection (140466362887416) from 172.17.0.2
2018-05-09 10:49:47,236 DEBUG: Received options response on connection (140466362888032) from 172.17.0.2
2018-05-09 10:49:59,767 DEBUG: [pid 62674] 0 clients connected
2018-05-09 10:49:59,767 DEBUG: [pid 62674] /bokeh_server has 0 sessions with 0 unused
2018-05-09 10:49:59,768 INFO: [pid 62674] Memory usage: 176.00 MB (RSS), 1159.00 MB (VMS)
2018-05-09 10:49:59,795 DEBUG: uncollected Documents: 2
2018-05-09 10:49:59,823 DEBUG: uncollected Sessions: 0
2018-05-09 10:49:59,865 DEBUG: uncollected Models: 0

What are these uncollected Documents? How can we delete them? They seem to always exist.

Thanks!
Corey

--
You received this message because you are subscribed to the Google Groups "Bokeh Discussion - Public" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [email protected].
To post to this group, send email to [email protected].
To view this discussion on the web visit https://groups.google.com/a/continuum.io/d/msgid/bokeh/2c20fde9-a14b-456a-8f0a-529880a37110%40continuum.io.
For more options, visit https://groups.google.com/a/continuum.io/d/optout.

Hi Bryan,

Alright so further investigation shows that the documents and modules are indeed created when a session is created, once the session is destroyed they are not increasing, but not decreasing either:

2018-05-14 12:00:35,536 DEBUG: [pid 11256] /bokeh_server has 1 sessions with 0 unused

2018-05-14 12:00:35,537 INFO: [pid 11256] Memory usage: 123.00 MB (RSS), 1194.00 MB (VMS)

2018-05-14 12:00:35,566 DEBUG: uncollected Documents: 2

2018-05-14 12:00:35,595 DEBUG: uncollected Sessions: 1

2018-05-14 12:00:35,635 DEBUG: uncollected Models: 48

2018-05-14 12:00:35,635 TRACE: Running session cleanup job

2018-05-14 12:00:40,537 TRACE: Running session cleanup job

2018-05-14 12:00:45,535 TRACE: Running session cleanup job

2018-05-14 12:00:49,535 TRACE: Running keep alive job

2018-05-14 12:00:50,535 TRACE: Running session cleanup job

2018-05-14 12:00:52,939 INFO: WebSocket connection closed: code=1001, reason=None

2018-05-14 12:00:55,535 TRACE: Running session cleanup job

2018-05-14 12:01:00,537 TRACE: Running session cleanup job

2018-05-14 12:01:00,537 DEBUG: Scheduling 1 sessions to discard

2018-05-14 12:01:00,537 DEBUG: Discarding session ‘b65b2409140e6d4c0ebd6958f2a504454cb02bbc4e26280933766248ac5523b5’ last in use 7596.798010000959 milliseconds ago

2018-05-14 12:01:00,537 DEBUG: Deleting 1 modules for <bokeh.document.document.Document object at 0x7f1931596668>

2018-05-14 12:01:00,603 TRACE: Session ‘b65b2409140e6d4c0ebd6958f2a504454cb02bbc4e26280933766248ac5523b5’ was successfully discarded

2018-05-14 12:01:05,540 TRACE: Running stats log job

2018-05-14 12:01:05,540 DEBUG: [pid 11256] 0 clients connected

2018-05-14 12:01:05,540 DEBUG: [pid 11256] /bokeh_server has 0 sessions with 0 unused

2018-05-14 12:01:05,541 INFO: [pid 11256] Memory usage: 123.00 MB (RSS), 1195.00 MB (VMS)

2018-05-14 12:01:05,581 DEBUG: uncollected Documents: 2

2018-05-14 12:01:05,621 DEBUG: uncollected Sessions: 1

2018-05-14 12:01:05,671 DEBUG: uncollected Models: 48

I stepped through the bokeh code and it seems to hit all the session.destroy, module cleanups and document destroy code you introduced in the memory leak PR so I’m not sure what exactly is happening.

I even tried adding some of the module removing and document deleting code you have in the document.destroy() method into server_lifecycle.py however exceptions are thrown because for example there are no more modules anymore associated to the session_context document anymore.

My app is fairly complicated but I will try to reproduce with something easier and post an example here.

···

On Friday, May 11, 2018 at 6:48:54 PM UTC+2, Bryan Van de ven wrote:

Hi,

To investigate in detail, we really need instructions (and code) to reproduce. I will say that an empty document with no models (which seems to be the case, as there are 0 uncollected models) should should take up perhaps hundred of bytes. Which isn’t to say it should’t be investigated, but previously entire arbitrarily large CDS structures or modules with large data frames could stick around, leaking MBs of GBs. What is the rate of increase of uncollected documents? Is there an increase over time at all? There may be a small number created that are simply overhead and will never go away, but that show up in that report because the scan is very coarse and does not consider whether the documents are internal overhead or were created to service a session. If the number is not increasing then it can be safely ignored.

Thanks,

Bryan

On May 10, 2018, at 22:37, ‘omearac’ via Bokeh Discussion - Public [email protected] wrote:

Okay it seems this may be related to the memory leak in the Bokeh server. Bryan introduced the new logging here: https://github.com/bokeh/bokeh/pull/7604/files

These uncollected Documents are objects that GC hasn’t collected yet…and never does even though our ‘app’ is running in the server but no user is using a browser at all.

Okay, so I think the way to maybe fix this is to use the lifecycle hook to use the new ‘destroy’ Document method introduced in the above PR since that also calls GC directly after deleting the document.

Will update on Monday.

On Wednesday, May 9, 2018 at 1:22:08 PM UTC+2, omearac wrote:

Hi everyone,

We started a bokeh server with the option --stats-log-frequency to see additional logging.

We are serving a bokeh app continuously: when the websocket is closed, the session is ‘discarded’ and then the document modules are deleted. However the bokeh server logs show output like:

2018-05-09 10:49:37,922 INFO: WebSocket connection closed: code=1001, reason=None

2018-05-09 10:49:44,768 DEBUG: Scheduling 1 sessions to discard

2018-05-09 10:49:44,768 DEBUG: Discarding session ‘73baecb12ac25adaa492f3af6f260551dd10c38d5f97b453c2eadecd047aa463’ last in use 6845.971878007054 milliseconds ago

2018-05-09 10:49:44,768 DEBUG: Deleting 1 modules for <bokeh.document.document.Document object at 0x7fc0dc73b7b8>

2018-05-09 10:49:47,234 DEBUG: Sending options message heartbeat on idle connection (140466362888032) 172.17.0.2

2018-05-09 10:49:47,235 DEBUG: Sending options message heartbeat on idle connection (140466362887416) 172.17.0.2

2018-05-09 10:49:47,235 DEBUG: Received options response on connection (140466362887416) from 172.17.0.2

2018-05-09 10:49:47,236 DEBUG: Received options response on connection (140466362888032) from 172.17.0.2

2018-05-09 10:49:59,767 DEBUG: [pid 62674] 0 clients connected

2018-05-09 10:49:59,767 DEBUG: [pid 62674] /bokeh_server has 0 sessions with 0 unused

2018-05-09 10:49:59,768 INFO: [pid 62674] Memory usage: 176.00 MB (RSS), 1159.00 MB (VMS)

2018-05-09 10:49:59,795 DEBUG: uncollected Documents: 2

2018-05-09 10:49:59,823 DEBUG: uncollected Sessions: 0

2018-05-09 10:49:59,865 DEBUG: uncollected Models: 0

What are these uncollected Documents? How can we delete them? They seem to always exist.

Thanks!

Corey


You received this message because you are subscribed to the Google Groups “Bokeh Discussion - Public” group.

To unsubscribe from this group and stop receiving emails from it, send an email to [email protected].

To post to this group, send email to [email protected].

To view this discussion on the web visit https://groups.google.com/a/continuum.io/d/msgid/bokeh/2c20fde9-a14b-456a-8f0a-529880a37110%40continuum.io.

For more options, visit https://groups.google.com/a/continuum.io/d/optout.

Another update to this thread. I dont know why but after some time the accumulated Documents, Sessions and Modules are almost all collected and then I get just a few Documents remaining, BUT the Memory Usage (RSS) never decreases ever, at any point.

2018-05-15 15:10:31,697 INFO: [pid 19] Memory usage: 1718.00 MB (RSS), 2915.00 MB (VMS)

2018-05-15 15:10:31,725 DEBUG: uncollected Documents: 3

2018-05-15 15:10:31,743 DEBUG: uncollected Sessions: 1

2018-05-15 15:10:31,769 DEBUG: uncollected Models: 117

2018-05-15 15:10:41,698 DEBUG: Scheduling 1 sessions to discard

2018-05-15 15:10:41,698 DEBUG: Discarding session ‘c0d1d0e300262493cf5fa5506990f7615557d49dab53c7c52eb7c60612249159’ last in use 13143.709682941437 milliseconds ago

2018-05-15 15:10:41,698 DEBUG: Deleting 1 modules for <bokeh.document.document.Document object at 0x7f8c2ebb82e8>

2018-05-15 15:11:01,697 DEBUG: [pid 19] 0 clients connected

2018-05-15 15:11:01,698 DEBUG: [pid 19] /bokeh_server has 0 sessions with 0 unused

2018-05-15 15:11:01,698 INFO: [pid 19] Memory usage: 1718.00 MB (RSS), 2915.00 MB (VMS)

2018-05-15 15:11:01,729 DEBUG: uncollected Documents: 2

2018-05-15 15:11:01,752 DEBUG: uncollected Sessions: 0

2018-05-15 15:11:01,786 DEBUG: uncollected Models: 0

···

On Mon, May 14, 2018 at 1:12 PM, ‘omearac’ via Bokeh Discussion - Public [email protected] wrote:

Hi Bryan,

Alright so further investigation shows that the documents and modules are indeed created when a session is created, once the session is destroyed they are not increasing, but not decreasing either:

2018-05-14 12:00:35,536 DEBUG: [pid 11256] /bokeh_server has 1 sessions with 0 unused

2018-05-14 12:00:35,537 INFO: [pid 11256] Memory usage: 123.00 MB (RSS), 1194.00 MB (VMS)

2018-05-14 12:00:35,566 DEBUG: uncollected Documents: 2

2018-05-14 12:00:35,595 DEBUG: uncollected Sessions: 1

2018-05-14 12:00:35,635 DEBUG: uncollected Models: 48

2018-05-14 12:00:35,635 TRACE: Running session cleanup job

2018-05-14 12:00:40,537 TRACE: Running session cleanup job

2018-05-14 12:00:45,535 TRACE: Running session cleanup job

2018-05-14 12:00:49,535 TRACE: Running keep alive job

2018-05-14 12:00:50,535 TRACE: Running session cleanup job

2018-05-14 12:00:52,939 INFO: WebSocket connection closed: code=1001, reason=None

2018-05-14 12:00:55,535 TRACE: Running session cleanup job

2018-05-14 12:01:00,537 TRACE: Running session cleanup job

2018-05-14 12:01:00,537 DEBUG: Scheduling 1 sessions to discard

2018-05-14 12:01:00,537 DEBUG: Discarding session ‘b65b2409140e6d4c0ebd6958f2a504454cb02bbc4e26280933766248ac5523b5’ last in use 7596.798010000959 milliseconds ago

2018-05-14 12:01:00,537 DEBUG: Deleting 1 modules for <bokeh.document.document.Document object at 0x7f1931596668>

2018-05-14 12:01:00,603 TRACE: Session ‘b65b2409140e6d4c0ebd6958f2a504454cb02bbc4e26280933766248ac5523b5’ was successfully discarded

2018-05-14 12:01:05,540 TRACE: Running stats log job

2018-05-14 12:01:05,540 DEBUG: [pid 11256] 0 clients connected

2018-05-14 12:01:05,540 DEBUG: [pid 11256] /bokeh_server has 0 sessions with 0 unused

2018-05-14 12:01:05,541 INFO: [pid 11256] Memory usage: 123.00 MB (RSS), 1195.00 MB (VMS)

2018-05-14 12:01:05,581 DEBUG: uncollected Documents: 2

2018-05-14 12:01:05,621 DEBUG: uncollected Sessions: 1

2018-05-14 12:01:05,671 DEBUG: uncollected Models: 48

I stepped through the bokeh code and it seems to hit all the session.destroy, module cleanups and document destroy code you introduced in the memory leak PR so I’m not sure what exactly is happening.

I even tried adding some of the module removing and document deleting code you have in the document.destroy() method into server_lifecycle.py however exceptions are thrown because for example there are no more modules anymore associated to the session_context document anymore.

My app is fairly complicated but I will try to reproduce with something easier and post an example here.

On Friday, May 11, 2018 at 6:48:54 PM UTC+2, Bryan Van de ven wrote:

Hi,

To investigate in detail, we really need instructions (and code) to reproduce. I will say that an empty document with no models (which seems to be the case, as there are 0 uncollected models) should should take up perhaps hundred of bytes. Which isn’t to say it should’t be investigated, but previously entire arbitrarily large CDS structures or modules with large data frames could stick around, leaking MBs of GBs. What is the rate of increase of uncollected documents? Is there an increase over time at all? There may be a small number created that are simply overhead and will never go away, but that show up in that report because the scan is very coarse and does not consider whether the documents are internal overhead or were created to service a session. If the number is not increasing then it can be safely ignored.

Thanks,

Bryan

On May 10, 2018, at 22:37, ‘omearac’ via Bokeh Discussion - Public [email protected] wrote:

Okay it seems this may be related to the memory leak in the Bokeh server. Bryan introduced the new logging here: https://github.com/bokeh/bokeh/pull/7604/files

These uncollected Documents are objects that GC hasn’t collected yet…and never does even though our ‘app’ is running in the server but no user is using a browser at all.

Okay, so I think the way to maybe fix this is to use the lifecycle hook to use the new ‘destroy’ Document method introduced in the above PR since that also calls GC directly after deleting the document.

Will update on Monday.

On Wednesday, May 9, 2018 at 1:22:08 PM UTC+2, omearac wrote:

Hi everyone,

We started a bokeh server with the option --stats-log-frequency to see additional logging.

We are serving a bokeh app continuously: when the websocket is closed, the session is ‘discarded’ and then the document modules are deleted. However the bokeh server logs show output like:

2018-05-09 10:49:37,922 INFO: WebSocket connection closed: code=1001, reason=None

2018-05-09 10:49:44,768 DEBUG: Scheduling 1 sessions to discard

2018-05-09 10:49:44,768 DEBUG: Discarding session ‘73baecb12ac25adaa492f3af6f260551dd10c38d5f97b453c2eadecd047aa463’ last in use 6845.971878007054 milliseconds ago

2018-05-09 10:49:44,768 DEBUG: Deleting 1 modules for <bokeh.document.document.Document object at 0x7fc0dc73b7b8>

2018-05-09 10:49:47,234 DEBUG: Sending options message heartbeat on idle connection (140466362888032) 172.17.0.2

2018-05-09 10:49:47,235 DEBUG: Sending options message heartbeat on idle connection (140466362887416) 172.17.0.2

2018-05-09 10:49:47,235 DEBUG: Received options response on connection (140466362887416) from 172.17.0.2

2018-05-09 10:49:47,236 DEBUG: Received options response on connection (140466362888032) from 172.17.0.2

2018-05-09 10:49:59,767 DEBUG: [pid 62674] 0 clients connected

2018-05-09 10:49:59,767 DEBUG: [pid 62674] /bokeh_server has 0 sessions with 0 unused

2018-05-09 10:49:59,768 INFO: [pid 62674] Memory usage: 176.00 MB (RSS), 1159.00 MB (VMS)

2018-05-09 10:49:59,795 DEBUG: uncollected Documents: 2

2018-05-09 10:49:59,823 DEBUG: uncollected Sessions: 0

2018-05-09 10:49:59,865 DEBUG: uncollected Models: 0

What are these uncollected Documents? How can we delete them? They seem to always exist.

Thanks!

Corey


You received this message because you are subscribed to the Google Groups “Bokeh Discussion - Public” group.

To unsubscribe from this group and stop receiving emails from it, send an email to [email protected].

To post to this group, send email to [email protected].io.

To view this discussion on the web visit https://groups.google.com/a/continuum.io/d/msgid/bokeh/2c20fde9-a14b-456a-8f0a-529880a37110%40continuum.io.

For more options, visit https://groups.google.com/a/continuum.io/d/optout.

You received this message because you are subscribed to the Google Groups “Bokeh Discussion - Public” group.

To unsubscribe from this group and stop receiving emails from it, send an email to [email protected].

To post to this group, send email to [email protected].

To view this discussion on the web visit https://groups.google.com/a/continuum.io/d/msgid/bokeh/83d735f2-46c9-45a8-8751-111490e9d71b%40continuum.io.

For more options, visit https://groups.google.com/a/continuum.io/d/optout.

Hi,

It's not really possible for me to investigate without code at this point. The PR that was merged (#7604) had a runnable test case in a referenced ML discussion. As described in the PR, the changes there resulted in seeing 450MB per session being added, but then being released when the sessions were released. If you are seeing something different, then something different is at work. These issues are some of the trickiest to look into, they absolutely necessitate having a complete test case to run and investigate.

Thanks,

Bryan

···

On May 15, 2018, at 09:05, 'Corey O'Meara' via Bokeh Discussion - Public <[email protected]> wrote:

Another update to this thread. I dont know why but after some time the accumulated Documents, Sessions and Modules are almost all collected and then I get just a few Documents remaining, BUT the Memory Usage (RSS) never decreases ever, at any point.

2018-05-15 15:10:31,697 INFO: [pid 19] Memory usage: 1718.00 MB (RSS), 2915.00 MB (VMS)
2018-05-15 15:10:31,725 DEBUG: uncollected Documents: 3
2018-05-15 15:10:31,743 DEBUG: uncollected Sessions: 1
2018-05-15 15:10:31,769 DEBUG: uncollected Models: 117
2018-05-15 15:10:41,698 DEBUG: Scheduling 1 sessions to discard
2018-05-15 15:10:41,698 DEBUG: Discarding session 'c0d1d0e300262493cf5fa5506990f7615557d49dab53c7c52eb7c60612249159' last in use 13143.709682941437 milliseconds ago
2018-05-15 15:10:41,698 DEBUG: Deleting 1 modules for <bokeh.document.document.Document object at 0x7f8c2ebb82e8>
2018-05-15 15:11:01,697 DEBUG: [pid 19] 0 clients connected
2018-05-15 15:11:01,698 DEBUG: [pid 19] /bokeh_server has 0 sessions with 0 unused
2018-05-15 15:11:01,698 INFO: [pid 19] Memory usage: 1718.00 MB (RSS), 2915.00 MB (VMS)
2018-05-15 15:11:01,729 DEBUG: uncollected Documents: 2
2018-05-15 15:11:01,752 DEBUG: uncollected Sessions: 0
2018-05-15 15:11:01,786 DEBUG: uncollected Models: 0

On Mon, May 14, 2018 at 1:12 PM, 'omearac' via Bokeh Discussion - Public <[email protected]> wrote:
Hi Bryan,

Alright so further investigation shows that the documents and modules are indeed created when a session is created, once the session is destroyed they are not increasing, but not decreasing either:

2018-05-14 12:00:35,536 DEBUG: [pid 11256] /bokeh_server has 1 sessions with 0 unused
2018-05-14 12:00:35,537 INFO: [pid 11256] Memory usage: 123.00 MB (RSS), 1194.00 MB (VMS)
2018-05-14 12:00:35,566 DEBUG: uncollected Documents: 2
2018-05-14 12:00:35,595 DEBUG: uncollected Sessions: 1
2018-05-14 12:00:35,635 DEBUG: uncollected Models: 48
2018-05-14 12:00:35,635 TRACE: Running session cleanup job
2018-05-14 12:00:40,537 TRACE: Running session cleanup job
2018-05-14 12:00:45,535 TRACE: Running session cleanup job
2018-05-14 12:00:49,535 TRACE: Running keep alive job
2018-05-14 12:00:50,535 TRACE: Running session cleanup job
2018-05-14 12:00:52,939 INFO: WebSocket connection closed: code=1001, reason=None
2018-05-14 12:00:55,535 TRACE: Running session cleanup job
2018-05-14 12:01:00,537 TRACE: Running session cleanup job
2018-05-14 12:01:00,537 DEBUG: Scheduling 1 sessions to discard
2018-05-14 12:01:00,537 DEBUG: Discarding session 'b65b2409140e6d4c0ebd6958f2a504454cb02bbc4e26280933766248ac5523b5' last in use 7596.798010000959 milliseconds ago
2018-05-14 12:01:00,537 DEBUG: Deleting 1 modules for <bokeh.document.document.Document object at 0x7f1931596668>
2018-05-14 12:01:00,603 TRACE: Session 'b65b2409140e6d4c0ebd6958f2a504454cb02bbc4e26280933766248ac5523b5' was successfully discarded
2018-05-14 12:01:05,540 TRACE: Running stats log job
2018-05-14 12:01:05,540 DEBUG: [pid 11256] 0 clients connected
2018-05-14 12:01:05,540 DEBUG: [pid 11256] /bokeh_server has 0 sessions with 0 unused
2018-05-14 12:01:05,541 INFO: [pid 11256] Memory usage: 123.00 MB (RSS), 1195.00 MB (VMS)
2018-05-14 12:01:05,581 DEBUG: uncollected Documents: 2
2018-05-14 12:01:05,621 DEBUG: uncollected Sessions: 1
2018-05-14 12:01:05,671 DEBUG: uncollected Models: 48

I stepped through the bokeh code and it seems to hit all the session.destroy, module cleanups and document destroy code you introduced in the memory leak PR so I'm not sure what exactly is happening.

I even tried adding some of the module removing and document deleting code you have in the document.destroy() method into server_lifecycle.py however exceptions are thrown because for example there are no more modules anymore associated to the session_context document anymore.

My app is fairly complicated but I will try to reproduce with something easier and post an example here.

On Friday, May 11, 2018 at 6:48:54 PM UTC+2, Bryan Van de ven wrote:
Hi,

To investigate in detail, we really need instructions (and code) to reproduce. I will say that an empty document with no models (which seems to be the case, as there are 0 uncollected models) should should take up perhaps hundred of bytes. Which isn't to say it should't be investigated, but previously entire arbitrarily large CDS structures or modules with large data frames could stick around, leaking MBs of GBs. What is the rate of increase of uncollected documents? Is there an increase over time at all? There may be a small number created that are simply overhead and will never go away, but that show up in that report because the scan is very coarse and does not consider whether the documents are internal overhead or were created to service a session. If the number is not increasing then it can be safely ignored.

Thanks,

Bryan

> On May 10, 2018, at 22:37, 'omearac' via Bokeh Discussion - Public <[email protected]> wrote:
>
> Okay it seems this may be related to the memory leak in the Bokeh server. Bryan introduced the new logging here: https://github.com/bokeh/bokeh/pull/7604/files
>
> These uncollected Documents are objects that GC hasn't collected yet...and never does even though our 'app' is running in the server but no user is using a browser at all.
>
> Okay, so I think the way to maybe fix this is to use the lifecycle hook to use the new 'destroy' Document method introduced in the above PR since that also calls GC directly after deleting the document.
>
> Will update on Monday.
>
>
> On Wednesday, May 9, 2018 at 1:22:08 PM UTC+2, omearac wrote:
> Hi everyone,
>
> We started a bokeh server with the option --stats-log-frequency to see additional logging.
>
> We are serving a bokeh app continuously: when the websocket is closed, the session is 'discarded' and then the document modules are deleted. However the bokeh server logs show output like:
>
> 2018-05-09 10:49:37,922 INFO: WebSocket connection closed: code=1001, reason=None
> 2018-05-09 10:49:44,768 DEBUG: Scheduling 1 sessions to discard
> 2018-05-09 10:49:44,768 DEBUG: Discarding session '73baecb12ac25adaa492f3af6f260551dd10c38d5f97b453c2eadecd047aa463' last in use 6845.971878007054 milliseconds ago
> 2018-05-09 10:49:44,768 DEBUG: Deleting 1 modules for <bokeh.document.document.Document object at 0x7fc0dc73b7b8>
> 2018-05-09 10:49:47,234 DEBUG: Sending options message heartbeat on idle connection (140466362888032) 172.17.0.2
> 2018-05-09 10:49:47,235 DEBUG: Sending options message heartbeat on idle connection (140466362887416) 172.17.0.2
> 2018-05-09 10:49:47,235 DEBUG: Received options response on connection (140466362887416) from 172.17.0.2
> 2018-05-09 10:49:47,236 DEBUG: Received options response on connection (140466362888032) from 172.17.0.2
> 2018-05-09 10:49:59,767 DEBUG: [pid 62674] 0 clients connected
> 2018-05-09 10:49:59,767 DEBUG: [pid 62674] /bokeh_server has 0 sessions with 0 unused
> 2018-05-09 10:49:59,768 INFO: [pid 62674] Memory usage: 176.00 MB (RSS), 1159.00 MB (VMS)
> 2018-05-09 10:49:59,795 DEBUG: uncollected Documents: 2
> 2018-05-09 10:49:59,823 DEBUG: uncollected Sessions: 0
> 2018-05-09 10:49:59,865 DEBUG: uncollected Models: 0
>
> What are these uncollected Documents? How can we delete them? They seem to always exist.
>
> Thanks!
> Corey
>
>
> --
> You received this message because you are subscribed to the Google Groups "Bokeh Discussion - Public" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to [email protected].
> To post to this group, send email to [email protected].
> To view this discussion on the web visit https://groups.google.com/a/continuum.io/d/msgid/bokeh/2c20fde9-a14b-456a-8f0a-529880a37110%40continuum.io.
> For more options, visit https://groups.google.com/a/continuum.io/d/optout.

--
You received this message because you are subscribed to the Google Groups "Bokeh Discussion - Public" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [email protected].
To post to this group, send email to [email protected].
To view this discussion on the web visit https://groups.google.com/a/continuum.io/d/msgid/bokeh/83d735f2-46c9-45a8-8751-111490e9d71b%40continuum.io.

For more options, visit https://groups.google.com/a/continuum.io/d/optout.

--
You received this message because you are subscribed to the Google Groups "Bokeh Discussion - Public" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [email protected].
To post to this group, send email to [email protected].
To view this discussion on the web visit https://groups.google.com/a/continuum.io/d/msgid/bokeh/CAAoKuh%2BThjVtWLcbN%3Dgg39dpaUE73oCouMtpKfaXiZkP%3DcC1uA%40mail.gmail.com.
For more options, visit https://groups.google.com/a/continuum.io/d/optout.