Profiling MRuby Code

The timers within mruby-profiler are relatively simple and in most code they tend to work very well. They do fail when interacting with any program which ends up doing a fair amount of work within C which ends up calling ruby methods from C. To elaborate on that, let’s first look at how mruby-profiler calculates how much time is spent at a given mruby opcode.

The mruby-profiler gem uses the code fetch hook within the mruby VM. Every time an opcode is executed by the mruby VM the code fetch hook is called. MRuby-profiler records the time when an instruction is fetched. When the next fetch occurs the difference in time is assumed to be the amount of time spent in the previous instruction.

Generally this model works well. For normal ruby code it’s completely accurate, for ruby calling simple C routines the appropriate amount of time is given to the OP_SEND instruction which lead to the C call, but it fails with a mixture of C/ruby calls. Consider the below sequence of events:

During step 2 no ruby opcodes will be observed by mruby-profiler. Thus, when step 3 occurs and a new VM opcode is fetched, then all the time that was spent in step 2 is attributed to the last instruction in step 1. Typically the last instruction of a mruby method would be OP_RETURN. So, if you spot an OP_RETURN which is taking much more time than it should, be aware that it may be counting time spent in a calling C function.

In general I’d say having method/instruction time presented as 'self-time' is preferable in a reasonably well architected system. Self-time presents how much time could effectively be saved by optimizing the method by itself without considering the rest of the code it ends up calling.

Self-time, however, can create a few problems with interpreting the results of mruby-profiler. If a hotspot function is called a large number of times, it can be tricky to backtrack which functions called it a significant number of times or with a particular type of data which took the hotspot function longer to evaluate. The lack of cumulative times also make it hard to evaluate if a particular function is 'expensive to call'. It is possible to have an 'expensive to call' function which does not use a significant amount of time with called functions which also do not use much time. If, however, there is a sufficiently deep call stack, then an innocuous function can still become very expensive in the cumulative sense (i.e. "death by a million cuts")

The last issue is one that’s more ruby specific. I’d say it’s fair to say that if you enjoy ruby you use blocks…​ You use them a lot. For those of you unfamiliar with what a block is here’s a simple example:

In the ruby code :method is called with the block (do..end). The block is encoded as a lambda function (the second irep) and method ends up calling the lambda. Just like in the very first example, with Fixnum#times, the cost involved with :method is associated with :method’s implementation and not the object.method call. When the block accepting method adds a significant amount of overhead it’s very easy to overlook using self-time and you should be aware of it when profiling. In the case of iteration, we’ll revisit block-method overhead later in this article.

While at the moment mruby-profiler doesn’t present cumulative time information it does capture it from the MRuby VM (or at least it appeared to when I looked at the source). It’s not in the most convenient format, but at least the data is there, it’s just the analysis which needs to be updated (and that’s all ruby). The mruby-profiler gem is still missing the functionality, but I imagine it could be added reasonably easily in the future.

Of course another limitation of using both mruby and mruby-profiler is that both of them are going to have more bugs than other tools with more widespread use. When I initially found mruby-profiler it tended to crash in a variety of ways for the codebase I was profiling (I’d recommend using the fixes I’ve proposed to mruby-profiler via a pull request if it hasn’t yet been merged). When I initially began using MRuby I encountered a few bugs, though MRuby has become a fair bit more stable over the past year. Lastly, while mruby-profiler does provide an output for kcachgrind, be aware that it is incomplete and there are some bugs in the output (though it is entirely unclear if they are from mruby’s debug info or a bug within mruby-profiler).

Like most interpreted languages, heavy mathematical operations aren’t 'fast'. Of course, they may be fast enough, but major gains can be made by using a compiled and heavily optimized language like C.

Consider the below ruby code:

The ruby VM instructions are reasonably quick, but when comparing 12 ruby opcodes to 4 assembly instructions (fld..fstps), it’s rather obvious that there’s going to be a pretty reasonable difference in speed. MRuby isn’t going to simplify any of the math that you supply it with and each opcode (simple or not) is going to take a fair bit longer than a single assembly instruction.

Accessing data stored in mruby classes isn’t all that cheap even for simple attributes. Each member access in idiomatic ruby results in a method call via OP_SEND. Evaluating each method call is relatively expensive compared to other opcodes and each call tends to involve a setup phase for the arguments of each method. In comparison for C to access member variables it’s as simple as fetching memory at an offset to the base of the structure.

The mruby VM is fast, but when dealing with these member variable references the overhead adds up. The relatively basic loop results in a 15 opcode body. Of those opcodes, 4 are method calls, and 4 involve setting up the method calls. C doesn’t even need a separate instruction to fetch the values due to the addressing modes that x86 provides. Additionally, C can recognize that the member variables are constant and calculate their affect once outside the loop body. That leaves 3 (fld..fstps) instructions in the loop body for a tight C loop.

Actually, going one step beyond, loops over large amounts of data are just bad for performance in MRuby due to the overhead introduced by Array#each/Array#map/etc.

In previous examples the loop overhead for C was neglected. For this example, 3 instructions: addq, cmpl, and jg are the overhead per loop iteration. Ruby’s is hidden in the :each method of the container. If you’re in an optimizing mindset, you might think that since :each is the idiomatic way to build loops in ruby it would be built to limit overhead.

Nope:

Translating that to VM instructions results in 25 opcodes overhead per loop with 4 method calls (:[], :call, :length, :length). Ouch…​

So, Array#each/Array#map/etc have a lot of overhead when you get to optimizing. What about other types of loops? A standard for loop is just an alias to :each. A while loop however avoids much of the setup and per iteration cost.

There’s still plenty of register shuffling with the while loop, but 6-7 opcodes of overhead per iteration and only one method call (:[]) sure beats 25 extra opcodes per loop. So, if you want to keep a hotspot in pure ruby, you might have more luck with inlining a while loop or using :each_index which is a middle ground in terms of cost.