Understanding oink output

Question

I am using oink to help determine the causes of memory bloat in an application, but I am having a hard time making sense of the output produced from oink (or making any actionable decisions based on it). If there is some documentation or blog that explains in more detail, that would be very useful (though I haven't been able to find any).

For instance, I have the following output from running my logs through oink:

---- MEMORY THRESHOLD ----
THRESHOLD: 10 MB

-- SUMMARY --
Worst Requests:
1. May 13 22:59:15, 69848 KB, api#action_1
2. May 13 22:56:15, 58128 KB, application#js_action
3. May 13 23:10:28, 12108 KB, application#js_action
4. May 13 23:10:46, 12108 KB, api#action_2
5. May 13 23:11:16, 12108 KB, api#update_action
6. May 13 23:11:21, 12108 KB, api#update_action
7. May 13 23:12:44, 11704 KB, api#update_action
8. May 13 23:13:44, 11704 KB, api#product_action
9. May 13 23:14:42, 11704 KB, application#js_action
10. May 13 23:16:11, 11704 KB, application#js_action

Worst Actions:
14, application#js_action
5, api#update_action
4, api#action_1
2, api#action_2
1, admin/products#index
1, admin/users#index
1, api#update_product
1, api#product_action

Aggregated Totals:
Action                          Max     Mean    Min     Total   Number of requests
application#js_action           58128   14408   10448   201724  14
api#action_1                    69848   25523   10664   102092  4
api#update_action               12108   11363   10448   56816   5
api#action_2                    12108   11512   10916   23024   2
api#product_action              11704   11704   11704   11704   1
api#update_product              10916   10916   10916   10916   1
admin/products#index            10548   10548   10548   10548   1
admin/users#index               10500   10500   10500   10500   1

If anyone can help me make sense of the output, it would be very much appreciated. For instance, what do each of the columns mean (I get that they're memory, but is it the total amount of memory that action takes?)

*Note - these results were ran with the memory option (not active record)

score 1 · Accepted Answer · answered May 15 '14 at 09:48

Lets start with the header :

---- MEMORY THRESHOLD ----
THRESHOLD: 10 MB

This gives the current setting of threshold for memory . i.e 10MB , You can change that using -m option.

example oink -m 20 path_to_log

Next comes the summary section:

-- SUMMARY --
Worst Requests:
1. May 13 22:59:15, 69848 KB, api#action_1
2. May 13 22:56:15, 58128 KB, application#js_action
3. May 13 23:10:28, 12108 KB, application#js_action
4. May 13 23:10:46, 12108 KB, api#action_2
5. May 13 23:11:16, 12108 KB, api#update_action
6. May 13 23:11:21, 12108 KB, api#update_action
7. May 13 23:12:44, 11704 KB, api#update_action
8. May 13 23:13:44, 11704 KB, api#product_action
9. May 13 23:14:42, 11704 KB, application#js_action
10. May 13 23:16:11, 11704 KB, application#js_action

It shows the worst requests made to the server from start and their corresponding timestamps.

Next comes the summary section:

Worst Actions:
14, application#js_action
5, api#update_action
4, api#action_1
2, api#action_2
1, admin/products#index
1, admin/users#index
1, api#update_product
1, api#product_action

This section has the number of requests made to a particular action.

Ex : application#js_action was called 14 times and its one of the worst in the memory usage.You can check the below section for its actual number of memory used.

Here we can see that number of requests are 14. Max/Min is the maximum/minimum memory used by one of the 14 requests. Mean is the Mean of all 14 requests memory usage.

Total is the sum of memory usage of all the requests.

Aggregated Totals:
Action                          Max     Mean    Min     Total   Number of requests
application#js_action           58128   14408   10448   201724  14
api#action_1                    69848   25523   10664   102092  4
api#update_action               12108   11363   10448   56816   5
api#action_2                    12108   11512   10916   23024   2
api#product_action              11704   11704   11704   11704   1
api#update_product              10916   10916   10916   10916   1
admin/products#index            10548   10548   10548   10548   1
admin/users#index               10500   10500   10500   10500   1

All the three sections are dependent. If you look at the "Aggregated totals" . You have Max memory usage is 58128 for application#js_action , If you want to know the time of this action you can see the first section "Worst Requests". It has a record

2. May 13 22:56:15, **58128 KB**, application#js_action

Now you know the worst actions fix them first, then go for the worst requests and find out why its happening at that particular time , May be you have some cronjob running which is making your server slow.

I have a similar question as the OP, which I would love to see addressed more thoroughly. The oink README talks about measuring "megabyte memory increase from the previous request", and the example of setting the threshold at 75MB says it will "find all actions which increase the heap size more than 75 MB." Am I right, then, in understanding that the output numbers refer to *increases to the process's memory heap caused by the action*, and not total memory used by the action? — Jacob, Jan 16 '15 at 00:48

Understanding oink output

1 Answers1