Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
bdmac opened this issue Apr 3, 2014 · 4 comments
Closed

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

bdmac opened this issue Apr 3, 2014 · 4 comments

Comments

@bdmac
Copy link

bdmac commented Apr 3, 2014

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
Copy link
Author

bdmac commented Apr 3, 2014

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
Copy link
Author

bdmac commented Apr 3, 2014

Relevant Heroku config:

AVAILABLE_MEMORY:                 512
PUMA_MAX_WORKERS:                 2

@bdmac
Copy link
Author

bdmac commented Apr 3, 2014

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

@bdmac bdmac mentioned this issue Apr 3, 2014
Closed
@schneems
Copy link
Owner

schneems commented Apr 5, 2014

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

@schneems schneems closed this as completed Apr 5, 2014
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@bdmac @schneems