search

schneems / puma_auto_tune

Puma performance without all the (T)pain
227 stars 19 forks source link

ERROR: Unknown user-defined format specifier "pss". #8

Closed bdmac closed 10 years ago

bdmac commented 10 years ago

This looks like it could be related to #2 #3 and #6 but I'm not positive.

It also seems like it may be related to the v1.0 updates in your get_process_mem gem?

Below is the log from Heroku for one of my web dynos shortly after updating from puma_worker_killer to puma_auto_tune (which included an update to get_process_mem along the way). Things started out OK until I hit a heavy page. As you can see below, I hit a few R14 memory errors (padding added around them so they stand out). The logs also include the output of log-runtime-metrics.

The memory usage reported by PumaAutoTune does not seem to match what is reported by log-runtime-metrics. The first time the R14 comes up, lrm reports 554M in use whereas the PAT stats around there report < 500M in use.

I have PAT configured with config.ram = Integer(ENV['AVAILABLE_MEMORY'] || 768) * 0.98 and ENV['AVAILABLE_MEMORY'] is set to 512.

Eventually, after 2x R14 errors, PAT detects the over memory condition. At that point it freaks the hell out dumping a ton of log entries stating that it's resizing to remove a worker and current_cluster_size=2. This goes on for quite a bit during which period we see two additional R14 errors.

Eventually towards the bottom is where things get REALLY interesting as we see 2014-04-03T22:57:03.602261+00:00 app[web.2]: ERROR: Unknown user-defined format specifier "pss". followed by what looks like help output for a linux command. That's what made me think of the changes to get_process_mem...


2014-04-03T22:52:35.780594+00:00 app[web.2]: PumaAutoTune (523s): All is well puma.resource_ram_mb=412.91455078125 puma.current_cluster_size=2
2014-04-03T22:52:46.070479+00:00 app[web.2]: PumaAutoTune (533s): All is well puma.resource_ram_mb=412.95751953125 puma.current_cluster_size=2
2014-04-03T22:52:48.533848+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#load_avg_1m=0.00 sample#load_avg_5m=0.02
2014-04-03T22:52:48.534064+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#memory_total=454.43MB sample#memory_rss=422.77MB sample#memory_cache=0.00MB sample#memory_swap=31.66MB sample#memory_pgpgin=292761pages sample#memory_pgpgout=184533pages
2014-04-03T22:52:56.359310+00:00 app[web.2]: PumaAutoTune (543s): All is well puma.resource_ram_mb=413.11376953125 puma.current_cluster_size=22014-04-03T22:53:06.657004+00:00 app[web.2]: PumaAutoTune (554s): All is well puma.resource_ram_mb=413.11767578125 puma.current_cluster_size=2
2014-04-03T22:53:09.643775+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#memory_total=454.76MB sample#memory_rss=423.09MB sample#memory_cache=0.00MB sample#memory_swap=31.66MB sample#memory_pgpgin=292849pages sample#memory_pgpgout=184537pages
2014-04-03T22:53:09.643663+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#load_avg_1m=0.00 sample#load_avg_5m=0.022014-04-03T22:53:16.990077+00:00 app[web.2]: PumaAutoTune (564s): All is well puma.resource_ram_mb=413.78955078125 puma.current_cluster_size=2
2014-04-03T22:53:27.317138+00:00 app[web.2]: PumaAutoTune (574s): All is well puma.resource_ram_mb=413.80322265625 puma.current_cluster_size=2
2014-04-03T22:53:30.473765+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#memory_total=454.93MB sample#memory_rss=423.57MB sample#memory_cache=0.00MB sample#memory_swap=31.36MB sample#memory_pgpgin=292974pages sample#memory_pgpgout=184539pages
2014-04-03T22:53:30.473571+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#load_avg_1m=0.00 sample#load_avg_5m=0.02
2014-04-03T22:53:37.595725+00:00 app[web.2]: PumaAutoTune (585s): All is well puma.resource_ram_mb=413.81103515625 puma.current_cluster_size=2
2014-04-03T22:53:47.883531+00:00 app[web.2]: PumaAutoTune (595s): All is well puma.resource_ram_mb=413.81103515625 puma.current_cluster_size=2
2014-04-03T22:53:51.584597+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#load_avg_1m=0.00 sample#load_avg_5m=0.02
2014-04-03T22:53:51.584794+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#memory_total=454.93MB sample#memory_rss=423.58MB sample#memory_cache=0.00MB sample#memory_swap=31.35MB sample#memory_pgpgin=292976pages sample#memory_pgpgout=184539pages
2014-04-03T22:53:58.215145+00:00 app[web.2]: PumaAutoTune (605s): All is well puma.resource_ram_mb=413.90869140625 puma.current_cluster_size=2
2014-04-03T22:54:08.510742+00:00 app[web.2]: PumaAutoTune (616s): All is well puma.resource_ram_mb=413.92822265625 puma.current_cluster_size=2
2014-04-03T22:54:12.726188+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#load_avg_1m=0.00 sample#load_avg_5m=0.02
2014-04-03T22:54:12.726279+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#memory_total=455.32MB sample#memory_rss=424.14MB sample#memory_cache=0.00MB sample#memory_swap=31.18MB sample#memory_pgpgin=293125pages sample#memory_pgpgout=184545pages sample#load_avg_1m=0.31 sample#load_avg_5m=0.09
2014-04-03T22:54:18.857547+00:00 app[web.2]: PumaAutoTune (626s): All is well puma.resource_ram_mb=414.45556640625 puma.current_cluster_size=2
2014-04-03T22:54:29.219669+00:00 app[web.2]: PumaAutoTune (636s): All is well puma.resource_ram_mb=414.47119140625 puma.current_cluster_size=2
2014-04-03T22:54:33.829524+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#load_avg_1m=0.00 sample#load_avg_5m=0.01
2014-04-03T22:54:33.829795+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#memory_total=455.38MB sample#memory_rss=424.21MB sample#memory_cache=0.00MB sample#memory_swap=31.17MB sample#memory_pgpgin=293142pages sample#memory_pgpgout=184545pages
2014-04-03T22:54:39.511561+00:00 app[web.2]: PumaAutoTune (647s): All is well puma.resource_ram_mb=414.47802734375 puma.current_cluster_size=2
2014-04-03T22:54:49.825462+00:00 app[web.2]: PumaAutoTune (657s): All is well puma.resource_ram_mb=414.48583984375 puma.current_cluster_size=2
2014-04-03T22:54:54.651851+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#load_avg_1m=0.00 sample#load_avg_5m=0.01
2014-04-03T22:54:54.652134+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#memory_total=455.39MB sample#memory_rss=424.23MB sample#memory_cache=0.00MB sample#memory_swap=31.16MB sample#memory_pgpgin=293147pages sample#memory_pgpgout=184545pages
2014-04-03T22:55:00.160780+00:00 app[web.2]: PumaAutoTune (667s): All is well puma.resource_ram_mb=414.57275390625 puma.current_cluster_size=2
2014-04-03T22:55:10.503061+00:00 app[web.2]: PumaAutoTune (678s): All is well puma.resource_ram_mb=414.74267578125 puma.current_cluster_size=2
2014-04-03T22:55:15.489438+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#load_avg_1m=0.00 sample#load_avg_5m=0.01
2014-04-03T22:55:15.489661+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#memory_total=455.80MB sample#memory_rss=424.78MB sample#memory_cache=0.00MB sample#memory_swap=31.02MB sample#memory_pgpgin=293295pages sample#memory_pgpgout=184551pages
2014-04-03T22:55:20.798634+00:00 app[web.2]: PumaAutoTune (688s): All is well puma.resource_ram_mb=415.10205078125 puma.current_cluster_size=2
2014-04-03T22:55:31.105872+00:00 app[web.2]: PumaAutoTune (698s): All is well puma.resource_ram_mb=415.11962890625 puma.current_cluster_size=2
2014-04-03T22:55:36.581235+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#load_avg_1m=0.00 sample#load_avg_5m=0.01
2014-04-03T22:55:36.581425+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#memory_total=455.87MB sample#memory_rss=424.86MB sample#memory_cache=0.00MB sample#memory_swap=31.01MB sample#memory_pgpgin=293316pages sample#memory_pgpgout=184551pages
2014-04-03T22:55:39.530912+00:00 app[web.2]: Started GET "/" for 199.101.130.203 at 2014-04-03 22:55:39 +0000
2014-04-03T22:55:40.579360+00:00 app[web.2]: Started GET "/admin" for 199.101.130.203 at 2014-04-03 22:55:40 +0000
2014-04-03T22:55:41.483870+00:00 app[web.2]: PumaAutoTune (709s): All is well puma.resource_ram_mb=422.78271484375 puma.current_cluster_size=2
2014-04-03T22:55:44.647601+00:00 app[web.2]: Dalli/SASL authenticating as defc01
2014-04-03T22:55:44.651047+00:00 app[web.2]: Dalli/SASL: defc01
2014-04-03T22:55:50.991822+00:00 app[web.2]: Started GET "/admin/reservations/forecast" for 199.101.130.203 at 2014-04-03 22:55:50 +0000
2014-04-03T22:55:51.808492+00:00 app[web.2]: PumaAutoTune (719s): All is well puma.resource_ram_mb=482.123046875 puma.current_cluster_size=2

2014-04-03T22:55:57.698228+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#load_avg_1m=0.00 sample#load_avg_5m=0.01
2014-04-03T22:55:57.698446+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#memory_total=554.64MB sample#memory_rss=511.98MB sample#memory_cache=0.00MB sample#memory_swap=42.66MB sample#memory_pgpgin=330543pages sample#memory_pgpgout=199476pages
2014-04-03T22:55:57.698978+00:00 heroku[web.2]: Process running mem=554M(108.3%)
2014-04-03T22:55:57.699167+00:00 heroku[web.2]: Error R14 (Memory quota exceeded)

2014-04-03T22:56:02.214733+00:00 app[web.2]: PumaAutoTune (729s): All is well puma.resource_ram_mb=492.1142578125 puma.current_cluster_size=2
2014-04-03T22:56:12.669443+00:00 app[web.2]: PumaAutoTune (740s): All is well puma.resource_ram_mb=493.787109375 puma.current_cluster_size=2

2014-04-03T22:56:18.532145+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#load_avg_1m=0.00 sample#load_avg_5m=0.01
2014-04-03T22:56:18.532363+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#memory_total=557.15MB sample#memory_rss=511.86MB sample#memory_cache=0.00MB sample#memory_swap=45.29MB sample#memory_pgpgin=334231pages sample#memory_pgpgout=203196pages
2014-04-03T22:56:18.532957+00:00 heroku[web.2]: Process running mem=557M(108.8%)
2014-04-03T22:56:18.533193+00:00 heroku[web.2]: Error R14 (Memory quota exceeded)

2014-04-03T22:56:22.966379+00:00 app[web.2]: PumaAutoTune (750s): All is well puma.resource_ram_mb=495.9755859375 puma.current_cluster_size=2

2014-04-03T22:56:33.264561+00:00 app[web.2]: PumaAutoTune (760s): Potential memory leak. Reaping largest worker puma.largest_worker_memory_mb=184.32958984375 puma.resource_ram_mb=507.9208984375 puma.current_cluster_size=2

2014-04-03T22:56:33.265947+00:00 app[web.2]: ** [NewRelic][04/03/14 22:56:33 +0000 43438e32-0482-4c93-a57b-7cbddca97800 (139)] INFO : Starting Agent shutdown
2014-04-03T22:56:33.570931+00:00 app[web.2]: PumaAutoTune (761s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.0234375 puma.current_cluster_size=2
2014-04-03T22:56:33.884070+00:00 app[web.2]: PumaAutoTune (761s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.6484375 puma.current_cluster_size=2
2014-04-03T22:56:34.182133+00:00 app[web.2]: PumaAutoTune (761s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=511.1005859375 puma.current_cluster_size=2
2014-04-03T22:56:34.476657+00:00 app[web.2]: PumaAutoTune (762s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=511.1044921875 puma.current_cluster_size=2
2014-04-03T22:56:34.819411+00:00 app[web.2]: PumaAutoTune (762s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=511.505859375 puma.current_cluster_size=2
2014-04-03T22:56:35.124558+00:00 app[web.2]: PumaAutoTune (762s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=511.55859375 puma.current_cluster_size=2
2014-04-03T22:56:35.421103+00:00 app[web.2]: PumaAutoTune (763s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=511.59765625 puma.current_cluster_size=2
2014-04-03T22:56:35.724105+00:00 app[web.2]: PumaAutoTune (763s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=511.7734375 puma.current_cluster_size=2
2014-04-03T22:56:36.100631+00:00 app[web.2]: PumaAutoTune (763s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=512.11328125 puma.current_cluster_size=2
2014-04-03T22:56:36.402873+00:00 app[web.2]: PumaAutoTune (763s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=512.33984375 puma.current_cluster_size=2
2014-04-03T22:56:36.687851+00:00 app[web.2]: PumaAutoTune (764s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=512.5859375 puma.current_cluster_size=2
2014-04-03T22:56:36.974310+00:00 app[web.2]: PumaAutoTune (764s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=512.8984375 puma.current_cluster_size=2
2014-04-03T22:56:37.266412+00:00 app[web.2]: PumaAutoTune (764s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=513.20703125 puma.current_cluster_size=2
2014-04-03T22:56:37.588899+00:00 app[web.2]: PumaAutoTune (765s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=508.42578125 puma.current_cluster_size=2
2014-04-03T22:56:37.876392+00:00 app[web.2]: PumaAutoTune (765s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=508.66015625 puma.current_cluster_size=2
2014-04-03T22:56:38.170068+00:00 app[web.2]: PumaAutoTune (765s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=508.85546875 puma.current_cluster_size=2
2014-04-03T22:56:38.459089+00:00 app[web.2]: PumaAutoTune (766s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.05859375 puma.current_cluster_size=2
2014-04-03T22:56:39.392804+00:00 app[web.2]: PumaAutoTune (766s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.93359375 puma.current_cluster_size=2

2014-04-03T22:56:39.688298+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#load_avg_1m=0.30 sample#load_avg_5m=0.08
2014-04-03T22:56:39.688298+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#memory_total=558.81MB sample#memory_rss=511.86MB sample#memory_cache=0.00MB sample#memory_swap=46.95MB sample#memory_pgpgin=349163pages sample#memory_pgpgout=218126pages
2014-04-03T22:56:39.688298+00:00 heroku[web.2]: Process running mem=558M(109.1%)
2014-04-03T22:56:39.688298+00:00 heroku[web.2]: Error R14 (Memory quota exceeded)

2014-04-03T22:56:39.785835+00:00 app[web.2]: PumaAutoTune (767s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.2109375 puma.current_cluster_size=2
2014-04-03T22:56:40.054542+00:00 app[web.2]: PumaAutoTune (767s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.3984375 puma.current_cluster_size=2
2014-04-03T22:56:40.363684+00:00 app[web.2]: PumaAutoTune (767s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.671875 puma.current_cluster_size=2
2014-04-03T22:56:40.673423+00:00 app[web.2]: PumaAutoTune (768s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.7421875 puma.current_cluster_size=2
2014-04-03T22:56:40.967557+00:00 app[web.2]: PumaAutoTune (768s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.8828125 puma.current_cluster_size=2
2014-04-03T22:56:41.272971+00:00 app[web.2]: PumaAutoTune (768s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=511.09375 puma.current_cluster_size=2
2014-04-03T22:56:41.572219+00:00 app[web.2]: PumaAutoTune (769s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=511.2265625 puma.current_cluster_size=2
2014-04-03T22:56:45.226157+00:00 app[web.2]: PumaAutoTune (772s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=512.9677734375 puma.current_cluster_size=2
2014-04-03T22:56:45.794920+00:00 app[web.2]: PumaAutoTune (773s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=508.4853515625 puma.current_cluster_size=2
2014-04-03T22:56:46.164291+00:00 app[web.2]: PumaAutoTune (773s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.2294921875 puma.current_cluster_size=2
2014-04-03T22:56:46.700974+00:00 app[web.2]: PumaAutoTune (774s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.4638671875 puma.current_cluster_size=2
2014-04-03T22:56:47.007994+00:00 app[web.2]: PumaAutoTune (774s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.5380859375 puma.current_cluster_size=2
2014-04-03T22:56:47.298024+00:00 app[web.2]: PumaAutoTune (774s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.6083984375 puma.current_cluster_size=2
2014-04-03T22:56:47.645833+00:00 app[web.2]: PumaAutoTune (775s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.7490234375 puma.current_cluster_size=2
2014-04-03T22:56:48.306624+00:00 app[web.2]: PumaAutoTune (775s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.1572265625 puma.current_cluster_size=2
2014-04-03T22:56:48.592850+00:00 app[web.2]: PumaAutoTune (776s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.6005859375 puma.current_cluster_size=2
2014-04-03T22:56:48.931248+00:00 app[web.2]: PumaAutoTune (776s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.7646484375 puma.current_cluster_size=2
2014-04-03T22:56:49.505146+00:00 app[web.2]: PumaAutoTune (777s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.603515625 puma.current_cluster_size=2
2014-04-03T22:56:49.793911+00:00 app[web.2]: PumaAutoTune (777s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.861328125 puma.current_cluster_size=2
2014-04-03T22:56:50.076765+00:00 app[web.2]: PumaAutoTune (777s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.005859375 puma.current_cluster_size=2
2014-04-03T22:56:50.364991+00:00 app[web.2]: PumaAutoTune (777s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.154296875 puma.current_cluster_size=2
2014-04-03T22:56:50.643288+00:00 app[web.2]: PumaAutoTune (778s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.302734375 puma.current_cluster_size=2
2014-04-03T22:56:51.163700+00:00 app[web.2]: PumaAutoTune (778s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.369140625 puma.current_cluster_size=2
2014-04-03T22:56:51.480510+00:00 app[web.2]: PumaAutoTune (779s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.5537109375 puma.current_cluster_size=2
2014-04-03T22:56:51.834838+00:00 app[web.2]: PumaAutoTune (779s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.240234375 puma.current_cluster_size=2
2014-04-03T22:56:52.155693+00:00 app[web.2]: PumaAutoTune (779s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.9697265625 puma.current_cluster_size=2
2014-04-03T22:56:52.453164+00:00 app[web.2]: PumaAutoTune (780s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.4033203125 puma.current_cluster_size=2
2014-04-03T22:56:52.739240+00:00 app[web.2]: PumaAutoTune (780s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.7431640625 puma.current_cluster_size=2
2014-04-03T22:56:53.040618+00:00 app[web.2]: PumaAutoTune (780s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.9560546875 puma.current_cluster_size=2
2014-04-03T22:56:53.328435+00:00 app[web.2]: PumaAutoTune (780s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.0576171875 puma.current_cluster_size=2
2014-04-03T22:56:53.683771+00:00 app[web.2]: PumaAutoTune (781s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.2080078125 puma.current_cluster_size=2
2014-04-03T22:56:54.203159+00:00 app[web.2]: PumaAutoTune (781s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.3603515625 puma.current_cluster_size=2
2014-04-03T22:56:54.487168+00:00 app[web.2]: PumaAutoTune (782s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.7744140625 puma.current_cluster_size=2
2014-04-03T22:56:54.775313+00:00 app[web.2]: PumaAutoTune (782s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.9658203125 puma.current_cluster_size=2
2014-04-03T22:56:55.125818+00:00 app[web.2]: PumaAutoTune (782s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=511.0302734375 puma.current_cluster_size=2
2014-04-03T22:56:55.411941+00:00 app[web.2]: PumaAutoTune (782s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=511.146484375 puma.current_cluster_size=2
2014-04-03T22:56:55.766499+00:00 app[web.2]: PumaAutoTune (783s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=505.892578125 puma.current_cluster_size=2
2014-04-03T22:56:58.256217+00:00 app[web.2]: PumaAutoTune (785s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=507.044921875 puma.current_cluster_size=2
2014-04-03T22:56:58.542269+00:00 app[web.2]: PumaAutoTune (786s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=507.2001953125 puma.current_cluster_size=2
2014-04-03T22:56:58.824870+00:00 app[web.2]: PumaAutoTune (786s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=507.3779296875 puma.current_cluster_size=2
2014-04-03T22:56:59.108087+00:00 app[web.2]: PumaAutoTune (786s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=507.5830078125 puma.current_cluster_size=2
2014-04-03T22:56:59.396642+00:00 app[web.2]: PumaAutoTune (786s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=507.755859375 puma.current_cluster_size=2
2014-04-03T22:56:59.683648+00:00 app[web.2]: PumaAutoTune (787s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=507.9013671875 puma.current_cluster_size=2
2014-04-03T22:56:59.973415+00:00 app[web.2]: PumaAutoTune (787s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=508.126953125 puma.current_cluster_size=2
2014-04-03T22:57:00.259133+00:00 app[web.2]: PumaAutoTune (787s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=508.4091796875 puma.current_cluster_size=2

2014-04-03T22:57:00.525306+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#load_avg_1m=0.50 sample#load_avg_5m=0.14
2014-04-03T22:57:00.525887+00:00 heroku[web.2]: source=web.2 dyno=heroku.11310907.43438e32-0482-4c93-a57b-7cbddca97800 sample#memory_total=580.07MB sample#memory_rss=511.90MB sample#memory_cache=0.00MB sample#memory_swap=68.18MB sample#memory_pgpgin=359410pages sample#memory_pgpgout=228364pages
2014-04-03T22:57:00.526708+00:00 heroku[web.2]: Process running mem=580M(113.3%)
2014-04-03T22:57:00.526880+00:00 heroku[web.2]: Error R14 (Memory quota exceeded)

2014-04-03T22:57:00.552630+00:00 app[web.2]: PumaAutoTune (788s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=508.6337890625 puma.current_cluster_size=2
2014-04-03T22:57:00.840535+00:00 app[web.2]: PumaAutoTune (788s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=508.935546875 puma.current_cluster_size=2
2014-04-03T22:57:01.140453+00:00 app[web.2]: PumaAutoTune (788s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.2080078125 puma.current_cluster_size=2
2014-04-03T22:57:01.555828+00:00 app[web.2]: PumaAutoTune (789s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.5361328125 puma.current_cluster_size=2
2014-04-03T22:57:01.839522+00:00 app[web.2]: PumaAutoTune (789s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.8515625 puma.current_cluster_size=2
2014-04-03T22:57:02.140469+00:00 app[web.2]: PumaAutoTune (789s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.1748046875 puma.current_cluster_size=2
2014-04-03T22:57:02.444057+00:00 app[web.2]: PumaAutoTune (790s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.66015625 puma.current_cluster_size=2
2014-04-03T22:57:02.749121+00:00 app[web.2]: PumaAutoTune (790s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.8193359375 puma.current_cluster_size=2
2014-04-03T22:57:03.041018+00:00 app[web.2]: PumaAutoTune (790s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=510.19140625 puma.current_cluster_size=2
2014-04-03T22:57:03.380043+00:00 app[web.2]: PumaAutoTune (790s): Cluster too large. Resizing to remove one worker puma.resource_ram_mb=509.9775390625 puma.current_cluster_size=2

2014-04-03T22:57:03.602261+00:00 app[web.2]: ERROR: Unknown user-defined format specifier "pss".
2014-04-03T22:57:03.602261+00:00 app[web.2]: ********* simple selection *********  ********* selection by list *********
2014-04-03T22:57:03.602261+00:00 app[web.2]: -A all processes                      -C by command name
2014-04-03T22:57:03.602261+00:00 app[web.2]: -N negate selection                   -G by real group ID (supports names)
2014-04-03T22:57:03.602261+00:00 app[web.2]: -a all w/ tty except session leaders  -U by real user ID (supports names)
2014-04-03T22:57:03.602261+00:00 app[web.2]: -d all except session leaders         -g by session OR by effective group name
2014-04-03T22:57:03.602261+00:00 app[web.2]: -e all processes                      -p by process ID
2014-04-03T22:57:03.602261+00:00 app[web.2]: T  all processes on this terminal     -s processes in the sessions given
2014-04-03T22:57:03.602261+00:00 app[web.2]: a  all w/ tty, including other users  -t by tty
2014-04-03T22:57:03.602261+00:00 app[web.2]: g  OBSOLETE -- DO NOT USE             -u by effective user ID (supports names)
2014-04-03T22:57:03.602517+00:00 app[web.2]: r  only running processes             U  processes for specified users
2014-04-03T22:57:03.602517+00:00 app[web.2]: x  processes w/o controlling ttys     t  by tty
2014-04-03T22:57:03.602517+00:00 app[web.2]: *********** output format **********  *********** long options ***********
2014-04-03T22:57:03.602517+00:00 app[web.2]: -o,o user-defined  -f full            --Group --User --pid --cols --ppid
2014-04-03T22:57:03.602517+00:00 app[web.2]: -j,j job control   s  signal          --group --user --sid --rows --info
2014-04-03T22:57:03.602517+00:00 app[web.2]: -O,O preloaded -o  v  virtual memory  --cumulative --format --deselect
2014-04-03T22:57:03.602517+00:00 app[web.2]: -l,l long          u  user-oriented   --sort --tty --forest --version
2014-04-03T22:57:03.602517+00:00 app[web.2]: -F   extra full    X  registers       --heading --no-heading --context
2014-04-03T22:57:03.602517+00:00 app[web.2]:                     ********* misc options *********
2014-04-03T22:57:03.602517+00:00 app[web.2]: -V,V  show version      L  list format codes  f  ASCII art forest
2014-04-03T22:57:03.602705+00:00 app[web.2]: -m,m,-L,-T,H  threads   S  children in sum    -y change -l format
2014-04-03T22:57:03.602705+00:00 app[web.2]: -M,Z  security data     c  true command name  -c scheduling class
2014-04-03T22:57:03.602705+00:00 app[web.2]: -w,w  wide output       n  numeric WCHAN,UID  -H process hierarchy
2014-04-03T22:57:03.791107+00:00 app[web.2]: ERROR: Unknown user-defined format specifier "pss".
2014-04-03T22:57:03.791107+00:00 app[web.2]: ********* simple selection *********  ********* selection by list *********
2014-04-03T22:57:03.791107+00:00 app[web.2]: -A all processes                      -C by command name
2014-04-03T22:57:03.791107+00:00 app[web.2]: -N negate selection                   -G by real group ID (supports names)
2014-04-03T22:57:03.791107+00:00 app[web.2]: -a all w/ tty except session leaders  -U by real user ID (supports names)
2014-04-03T22:57:03.791107+00:00 app[web.2]: -d all except session leaders         -g by session OR by effective group name
2014-04-03T22:57:03.791107+00:00 app[web.2]: -e all processes                      -p by process ID
2014-04-03T22:57:03.791107+00:00 app[web.2]: T  all processes on this terminal     -s processes in the sessions given
2014-04-03T22:57:03.791107+00:00 app[web.2]: a  all w/ tty, including other users  -t by tty
2014-04-03T22:57:03.791107+00:00 app[web.2]: g  OBSOLETE -- DO NOT USE             -u by effective user ID (supports names)
2014-04-03T22:57:03.791418+00:00 app[web.2]: r  only running processes             U  processes for specified users
2014-04-03T22:57:03.791418+00:00 app[web.2]: x  processes w/o controlling ttys     t  by tty
2014-04-03T22:57:03.791418+00:00 app[web.2]: *********** output format **********  *********** long options ***********
2014-04-03T22:57:03.791418+00:00 app[web.2]: -o,o user-defined  -f full            --Group --User --pid --cols --ppid
2014-04-03T22:57:03.791418+00:00 app[web.2]: -j,j job control   s  signal          --group --user --sid --rows --info
2014-04-03T22:57:03.791418+00:00 app[web.2]: -O,O preloaded -o  v  virtual memory  --cumulative --format --deselect
2014-04-03T22:57:03.791418+00:00 app[web.2]: -l,l long          u  user-oriented   --sort --tty --forest --version
2014-04-03T22:57:03.791418+00:00 app[web.2]: -F   extra full    X  registers       --heading --no-heading --context
2014-04-03T22:57:03.791418+00:00 app[web.2]:                     ********* misc options *********
2014-04-03T22:57:03.791418+00:00 app[web.2]: -V,V  show version      L  list format codes  f  ASCII art forest
2014-04-03T22:57:03.791646+00:00 app[web.2]: -m,m,-L,-T,H  threads   S  children in sum    -y change -l format
2014-04-03T22:57:03.791646+00:00 app[web.2]: -M,Z  security data     c  true command name  -c scheduling class
2014-04-03T22:57:03.791646+00:00 app[web.2]: -w,w  wide output       n  numeric WCHAN,UID  -H process hierarchy
bdmac commented 10 years ago

FWIW here is my initializer:

PumaAutoTune.config do |config|
  config.ram = Integer(ENV['AVAILABLE_MEMORY'] || 768) * 0.98 # memory * percent utilization
  # Set our max_workers to what is in the ENV var + 1 because
  # PumaAutoTune uses new worker count < max_workers. That means
  # w/out adding 1 with a PUMA_MAX_WORKERS of 5 we would only
  # ever actually run 4... seems counter-intuitive so +1.
  config.max_workers = Integer(ENV['PUMA_MAX_WORKERS'] || 3) + 1
end
PumaAutoTune.start
bdmac commented 10 years ago

Relevant Heroku config:

AVAILABLE_MEMORY:                 512
PUMA_MAX_WORKERS:                 2
bdmac commented 10 years ago

Further digging implicates the get_process_mem gem even more so I will open an issue there and reference this one. Running a bash shell on Heroku and trying to run what it looks like get_process_mem would run from there results in the exact output I see in my web dyno logs above:

$ heroku run bash --remote staging
Running `bash` attached to terminal... up, run.7561
~ $ ps
  PID TTY          TIME CMD
    2 ?        00:00:00 bash
    3 ?        00:00:00 ps
~ $ ps -o pss= -p 2
ERROR: Unknown user-defined format specifier "pss".
********* simple selection *********  ********* selection by list *********
-A all processes                      -C by command name
-N negate selection                   -G by real group ID (supports names)
-a all w/ tty except session leaders  -U by real user ID (supports names)
-d all except session leaders         -g by session OR by effective group name
-e all processes                      -p by process ID
T  all processes on this terminal     -s processes in the sessions given
a  all w/ tty, including other users  -t by tty
g  OBSOLETE -- DO NOT USE             -u by effective user ID (supports names)
r  only running processes             U  processes for specified users
x  processes w/o controlling ttys     t  by tty
*********** output format **********  *********** long options ***********
-o,o user-defined  -f full            --Group --User --pid --cols --ppid
-j,j job control   s  signal          --group --user --sid --rows --info
-O,O preloaded -o  v  virtual memory  --cumulative --format --deselect
-l,l long          u  user-oriented   --sort --tty --forest --version
-F   extra full    X  registers       --heading --no-heading --context
                    ********* misc options *********
-V,V  show version      L  list format codes  f  ASCII art forest
-m,m,-L,-T,H  threads   S  children in sum    -y change -l format
-M,Z  security data     c  true command name  -c scheduling class
-w,w  wide output       n  numeric WCHAN,UID  -H process hierarchy
schneems commented 10 years ago

I've updated get_process_mem you can bundle update get_process_mem to fix this. Thanks for reporting! Sorry for the trouble :(