Memory is running out and Discourse stops working

[sam]

yes, its related to view tracking

[DeanMarkTaylor]

Thanks @sam!

So I have ran rebuild from the command line

root@forum:/var/discourse# ./launcher rebuild app
WARNING: No swap limit support
Updating discourse docker
remote: Counting objects: 11, done.
...

~Build Start: 2015-02-10T07:37:02.391921
~Build End: 2015-02-10T07:48:42.554345

Current system status

  System information as of Mon Feb  9 21:50:43 EST 2015

  System load:  0.1                Processes:              121
  Usage of /:   63.1% of 39.25GB   Users logged in:        1
  Memory usage: 78%                IP address for eth0:    
  Swap usage:   2%                 IP address for docker0: 

Current version: Discourse 1.2.0.beta6 - https://github.com/discourse/discourse version 0ce6524153b7e5545a834d2edf1a6b0de1cdcaef

Now we play the waiting game.

[DeanMarkTaylor]

Memory stats for reference - might be useful when comparing to non-working state if occurs again.
(unable to run with ?full=1 as ends up reporting Bad Gateway).

forum pid:128 unicorn worker     E production  c config/unicorn conf rb

GC STATS:
count: 51
heap_used: 2657
heap_length: 2937
heap_increment: 280
heap_live_num: 570066
heap_free_num: 510811
heap_final_num: 0
total_allocated_object: 5559315
total_freed_object: 4989249

Objects:
TOTAL: 1080875
FREE: 510762
T_STRING: 295318
T_ARRAY: 72002
T_DATA: 66176
T_OBJECT: 47373
T_NODE: 41502
T_HASH: 25286
T_CLASS: 11559
T_REGEXP: 3680
T_ICLASS: 3382
T_MODULE: 1658
T_STRUCT: 1234
T_RATIONAL: 892
T_MATCH: 15
T_BIGNUM: 14
T_FLOAT: 11
T_FILE: 10
T_COMPLEX: 1

Process Info:
Name:	ruby
State:	S (sleeping)
Tgid:	128
Ngid:	0
Pid:	128
PPid:	66
TracerPid:	0
Uid:	1000	1000	1000	1000
Gid:	33	33	33	33
FDSize:	64
Groups:	33 
VmPeak:	 1044208 kB
VmSize:	 1044204 kB
VmLck:	       0 kB
VmPin:	       0 kB
VmHWM:	  226068 kB
VmRSS:	  226068 kB
VmData:	  822488 kB
VmStk:	     136 kB
VmExe:	    2736 kB
VmLib:	   25964 kB
VmPTE:	     996 kB
VmSwap:	       0 kB
Threads:	7
SigQ:	0/15845
SigPnd:	0000000000000000
ShdPnd:	0000000000000000
SigBlk:	0000000000000000
SigIgn:	0000000008301801
SigCgt:	0000000182006646
CapInh:	00000000a80425fb
CapPrm:	0000000000000000
CapEff:	0000000000000000
CapBnd:	00000000a80425fb
Seccomp:	0
Cpus_allowed:	3
Cpus_allowed_list:	0-1
Mems_allowed:	00000000,00000001
Mems_allowed_list:	0
voluntary_ctxt_switches:	1080
nonvoluntary_ctxt_switches:	2636


Classes:
Class report omitted use ?full=1 to include it

[DeanMarkTaylor]

So this is a new bug related to the additional view tracking data you added?

yes, its related to view tracking

Looking though the code changes the traffic related changes occured ~5-6 days ago:
https://github.com/discourse/discourse/commit/c9adfa65a073e3071c3083fc36397a222b1aa2dc
https://github.com/discourse/discourse/commit/e105f0965c2cfad32b74d157d972f90c75e64e84

However if the following topic is related - it occurred ~10 days ago:

Memory Usage and Blank Pages

I’ve had an intermittent issue with my Discourse install where all I see is a blank page when I try to visit it. If I sudo reboot everything goes back to normal. This has been happening probably about once per week. I’m on the Digital Ocean 2 GB RAM plan and my community is on the smaller end (I think – I’m not sure how community size is defined). Anyway, have a feeling the problem is related to the memory usage. The past two times I’ve had to reboot here were the stats: System load: 0.54 Usag…

This is more of an FYI to make sure bases are covered.

[codinghorror]

There’s also an issue where we are being sloppy with Redis and storing

1. Way, way too many “permanent” keys
2. Too large keys (on the key side, the key is absurdly long)

So we need to fix that as well and I believe it is an independent issue.

[DeanMarkTaylor]

Just noticed this in admin on current build:

EDIT: Created separate bug:

Unexpected ([missing {{size} value] free) in admin for uploads

Continuing the discussion from Low memory / ImageMagicK / White pages: Current version: Discourse 1.2.0.beta6 - https://github.com/discourse/discourse version 0ce6524153b7e5545a834d2edf1a6b0de1cdcaef After refreshing the page the it’s now correctly displaying details. [image] Perhaps the first load kicks off a task? (the traffic numbers were also all zeros the first time).

[DeanMarkTaylor]

There’s also an issue where we are being sloppy with Redis and storing

Way, way too many “permanent” keys
Too large keys (on the key side, the key is absurdly long)

So we need to fix that as well and I believe it is an independent issue.

FYI - this issue was originally reported / experienced by me on a build from ~6 days ago, I believe this was prior to tracking being added?
https://github.com/discourse/discourse/commit/8689c85b54efccbccfa216c800522e5ba1a79dd1

[Brideau]

Hey Sam, my memory usage dipped briefly after updating (assuming it’s because the server restarted), but it’s creeping upward at exactly the same rate as before (~1MB/min).

[sam]

What does admin/memory_stats show you?

[sam]

I spent more time on this today, I cut down our initial boot memory by 10%.

I am not noticing any extreme growth around ruby heaps they seem fine, not seeing a leak there. Also added a large object report into ?full=true so we can catch any objects that just keep growing.

Also RSS and Peak seem to be pretty stable.

[DeanMarkTaylor]

I spent more time on this today, I cut down our initial boot memory by 10%.

Well done!

Also added a large object report into ?full=true so we can catch any objects that just keep growing.

I mentioned before I have been unable to run with ?full=1.

(unable to run with ?full=1 as ends up reporting Bad Gateway).

Would you like me to update?
Or get the current status (what commands would you like me to run?), then update?

[sam]

Get current status and then update, full=1 is intense but it only takes 2-3 seconds on meta, I guess droplets can be slow.

[sam]

Wait, so stuff lasted for 24 hours? Was it working for 24 hours in a row prior? Very curious to see stats.

[DeanMarkTaylor]

##/admin/memory_stats output

forum pid:1207 unicorn worker 1   E production  c config/unicorn conf rb

GC STATS:
count: 295
heap_used: 2937
heap_length: 2937
heap_increment: 0
heap_live_num: 595662
heap_free_num: 599113
heap_final_num: 0
total_allocated_object: 121166824
total_freed_object: 120571162

Objects:
TOTAL: 1194773
FREE: 599064
T_STRING: 304782
T_ARRAY: 77713
T_DATA: 68404
T_OBJECT: 52478
T_NODE: 41734
T_HASH: 27694
T_CLASS: 11619
T_REGEXP: 3746
T_ICLASS: 3629
T_MODULE: 1661
T_STRUCT: 1305
T_RATIONAL: 891
T_MATCH: 15
T_BIGNUM: 14
T_FILE: 12
T_FLOAT: 11
T_COMPLEX: 1

Process Info:
Name:	ruby
State:	S (sleeping)
Tgid:	1207
Ngid:	0
Pid:	1207
PPid:	66
TracerPid:	0
Uid:	1000	1000	1000	1000
Gid:	33	33	33	33
FDSize:	64
Groups:	33 
VmPeak:	 1252100 kB
VmSize:	 1252096 kB
VmLck:	       0 kB
VmPin:	       0 kB
VmHWM:	  357100 kB
VmRSS:	  332376 kB
VmData:	 1028312 kB
VmStk:	     136 kB
VmExe:	    2736 kB
VmLib:	   25976 kB
VmPTE:	    1416 kB
VmSwap:	  100388 kB
Threads:	7
SigQ:	0/15845
SigPnd:	0000000000000000
ShdPnd:	0000000000000000
SigBlk:	0000000000000000
SigIgn:	0000000008301801
SigCgt:	0000000182006646
CapInh:	00000000a80425fb
CapPrm:	0000000000000000
CapEff:	0000000000000000
CapBnd:	00000000a80425fb
Seccomp:	0
Cpus_allowed:	3
Cpus_allowed_list:	0-1
Mems_allowed:	00000000,00000001
Mems_allowed_list:	0
voluntary_ctxt_switches:	160773
nonvoluntary_ctxt_switches:	475835


Classes:
Class report omitted use ?full=1 to include it

##Running /admin/memory_stats?full=1
After waiting just displays

[DeanMarkTaylor]

Differences in memory stats in visual (before update.)

[DeanMarkTaylor]

Before update.

  System information as of Tue Feb 10 06:46:55 EST 2015

  System load:  0.05               Processes:              128
  Usage of /:   63.9% of 39.25GB   Users logged in:        1
  Memory usage: 69%                IP address for eth0:    
  Swap usage:   4%                 IP address for docker0:

[sam]

You are looking at different pids there, each time you run it may hit a different unicorn worker.

Memory looks fine there btw.

[DeanMarkTaylor]

Refreshing multiple times only got me workers 1 and 2 - here is two:
##Before Update
###Worker 2

forum pid:16116 unicorn worker 2   E production  c config/unicorn conf rb

GC STATS:
count: 52
heap_used: 2937
heap_length: 2937
heap_increment: 0
heap_live_num: 574092
heap_free_num: 620714
heap_final_num: 0
total_allocated_object: 5894241
total_freed_object: 5320149

Objects:
TOTAL: 1194778
FREE: 620639
T_STRING: 298113
T_ARRAY: 72261
T_DATA: 66426
T_OBJECT: 47993
T_NODE: 41503
T_HASH: 25365
T_CLASS: 11554
T_REGEXP: 3682
T_ICLASS: 3382
T_MODULE: 1659
T_STRUCT: 1257
T_RATIONAL: 891
T_MATCH: 15
T_BIGNUM: 14
T_FILE: 12
T_FLOAT: 11
T_COMPLEX: 1

Process Info:
Name:	ruby
State:	S (sleeping)
Tgid:	16116
Ngid:	0
Pid:	16116
PPid:	66
TracerPid:	0
Uid:	1000	1000	1000	1000
Gid:	33	33	33	33
FDSize:	64
Groups:	33 
VmPeak:	 1057516 kB
VmSize:	 1056492 kB
VmLck:	       0 kB
VmPin:	       0 kB
VmHWM:	  189504 kB
VmRSS:	  189504 kB
VmData:	  834776 kB
VmStk:	     136 kB
VmExe:	    2736 kB
VmLib:	   25964 kB
VmPTE:	    1028 kB
VmSwap:	   44644 kB
Threads:	7
SigQ:	0/15845
SigPnd:	0000000000000000
ShdPnd:	0000000000000000
SigBlk:	0000000000000000
SigIgn:	0000000008301801
SigCgt:	0000000182006646
CapInh:	00000000a80425fb
CapPrm:	0000000000000000
CapEff:	0000000000000000
CapBnd:	00000000a80425fb
Seccomp:	0
Cpus_allowed:	3
Cpus_allowed_list:	0-1
Mems_allowed:	00000000,00000001
Mems_allowed_list:	0
voluntary_ctxt_switches:	2427
nonvoluntary_ctxt_switches:	4392


Classes:
Class report omitted use ?full=1 to include it

[DeanMarkTaylor]

##Update Complete

Now running Discourse 1.2.0.beta6 - https://github.com/discourse/discourse version 38279c79c9941426c579ea0ee133b27786cdf4c6

####Approx build timestamps

Start 2015-02-11T09:44:37.869556
End 2015-02-11T09:54:07.770672

Memory Stats

####Worker

forum pid:119 unicorn worker     E production  c config/unicorn conf rb

GC STATS:
count: 53
heap_used: 3015
heap_length: 3015
heap_increment: 0
heap_live_num: 488867
heap_free_num: 737639
heap_final_num: 0
total_allocated_object: 4404260
total_freed_object: 3915393

Objects:
TOTAL: 1226503
FREE: 737589
T_STRING: 270131
T_DATA: 60843
T_ARRAY: 52132
T_NODE: 37200
T_HASH: 25831
T_OBJECT: 24087
T_CLASS: 9436
T_REGEXP: 3379
T_ICLASS: 3011
T_MODULE: 1367
T_RATIONAL: 891
T_STRUCT: 559
T_MATCH: 15
T_BIGNUM: 12
T_FLOAT: 11
T_FILE: 8
T_COMPLEX: 1

Process Info:
Name:	ruby
State:	S (sleeping)
Tgid:	119
Ngid:	0
Pid:	119
PPid:	66
TracerPid:	0
Uid:	1000	1000	1000	1000
Gid:	33	33	33	33
FDSize:	64
Groups:	33 
VmPeak:	  455800 kB
VmSize:	  451708 kB
VmLck:	       0 kB
VmPin:	       0 kB
VmHWM:	  198712 kB
VmRSS:	  198452 kB
VmData:	  234216 kB
VmStk:	     136 kB
VmExe:	    2736 kB
VmLib:	   25864 kB
VmPTE:	     868 kB
VmSwap:	       0 kB
Threads:	6
SigQ:	0/15845
SigPnd:	0000000000000000
ShdPnd:	0000000000000000
SigBlk:	0000000000000000
SigIgn:	0000000008301801
SigCgt:	0000000182006646
CapInh:	00000000a80425fb
CapPrm:	0000000000000000
CapEff:	0000000000000000
CapBnd:	00000000a80425fb
Seccomp:	0
Cpus_allowed:	3
Cpus_allowed_list:	0-1
Mems_allowed:	00000000,00000001
Mems_allowed_list:	0
voluntary_ctxt_switches:	397
nonvoluntary_ctxt_switches:	1134


Classes:
Class report omitted use ?full=1 to include it

####Worker 2

forum pid:142 unicorn worker 2   E production  c config/unicorn conf rb

GC STATS:
count: 52
heap_used: 3015
heap_length: 3015
heap_increment: 0
heap_live_num: 486912
heap_free_num: 739594
heap_final_num: 0
total_allocated_object: 4338328
total_freed_object: 3851416

Objects:
TOTAL: 1226503
FREE: 739544
T_STRING: 268693
T_DATA: 60754
T_ARRAY: 52186
T_NODE: 37175
T_HASH: 25727
T_OBJECT: 23797
T_CLASS: 9428
T_REGEXP: 3379
T_ICLASS: 2973
T_MODULE: 1366
T_RATIONAL: 891
T_STRUCT: 542
T_MATCH: 15
T_BIGNUM: 12
T_FLOAT: 11
T_FILE: 9
T_COMPLEX: 1

Process Info:
Name:	ruby
State:	S (sleeping)
Tgid:	142
Ngid:	0
Pid:	142
PPid:	66
TracerPid:	0
Uid:	1000	1000	1000	1000
Gid:	33	33	33	33
FDSize:	64
Groups:	33 
VmPeak:	  451712 kB
VmSize:	  451708 kB
VmLck:	       0 kB
VmPin:	       0 kB
VmHWM:	  198580 kB
VmRSS:	  198580 kB
VmData:	  234216 kB
VmStk:	     136 kB
VmExe:	    2736 kB
VmLib:	   25864 kB
VmPTE:	     868 kB
VmSwap:	       0 kB
Threads:	6
SigQ:	0/15845
SigPnd:	0000000000000000
ShdPnd:	0000000000000000
SigBlk:	0000000000000000
SigIgn:	0000000008301801
SigCgt:	0000000182006646
CapInh:	00000000a80425fb
CapPrm:	0000000000000000
CapEff:	0000000000000000
CapBnd:	00000000a80425fb
Seccomp:	0
Cpus_allowed:	3
Cpus_allowed_list:	0-1
Mems_allowed:	00000000,00000001
Mems_allowed_list:	0
voluntary_ctxt_switches:	362
nonvoluntary_ctxt_switches:	1011


Classes:
Class report omitted use ?full=1 to include it

[DeanMarkTaylor]

####Post build / update system info

  System information as of Wed Feb 11 04:38:26 EST 2015

  System load:  0.39               Processes:              122
  Usage of /:   47.8% of 39.25GB   Users logged in:        0
  Memory usage: 59%                IP address for eth0:    
  Swap usage:   53%                IP address for docker0: