Add profiling support

[macournoyer]

Right now, only Ruby Liquid has profiling. Profiling Liquid templates in production triggers Ruby Liquid to render the template, not Liquid::C. This is leading us on the wrong paths RE what to optimize.

I need to look at how other VMs are doing profiling with low overhead.

[dylanahsmith]

Profiling Liquid templates in production

Is that something we are using? Since it doesn't look like we are using the profile: true Liquid::Tempate.parse option.

triggers Ruby Liquid to render the template, not Liquid::C. This is leading us on the wrong paths RE what to optimize.

Do you mean "us" as implementers of the liquid API? Since I believe we use stackprof for profiling our code in production. That will profile rendering with Liquid::C, although it won't show where the time is spent in the C code. For that purpose, we will want a sampling C profiler, which works like stackprof, but gets the C stack trace periodically instead of the ruby stack trace.

For development of liquid-c on MacOS, I've added a c_profile rake task that works with Xcode's instruments command (https://github.com/Shopify/liquid-c/pull/62).

I need to look at how other VMs are doing profiling with low overhead.

We should also allow template authors to profile their liquid code.

A sampling profile works better for a single tenant use case, where it can be used across renders and capture. If we are just trying to profile a single render, then we may not collect enough samples. If we increase the sampling frequency to collect more samples, then we add more significant overhead. For local development, we render multiple times in a loop to collect enough samples with a sampling profiler, but naturally that redundant rendering is a significant overhead.

If we did want to implement a sampling profiler, then we could expose a stack of liquid source locations from the Liquid::Context that could be used by a sampler.

Another option would be to add instrumentation instructions to the VM code to collect timing information. That is essentially how the ruby liquid profiler works, however, we could do that more efficiently from C code. We would probably want to expose a different ruby API for it though.

[macournoyer]

Is that something we are using? Since it doesn't look like we are using the profile: true Liquid::Tempate.parse option.

Yes, through the Theme Inspector that customers are using, and employees too.

Do you mean "us" as implementers of the liquid API? Since I believe we use stackprof for profiling our code in production. That will profile rendering with Liquid::C, although it won't show where the time is spent in the C code. For that purpose, we will want a sampling C profiler, which works like stackprof, but gets the C stack trace periodically instead of the ruby stack trace.

Sorry I meant "us" as the team I was working with debugging Liquid issues on a merchant site. But it could be merchants themselves, or theme designers.

For development of liquid-c on MacOS, I've added a c_profile rake task that works with Xcode's instruments command (#62).

Saw this! Very cool.

We should also allow template authors to profile their liquid code.

Yes, this is what I had in mind writing the issue. Template authors are currently optimizing their templates based on Liquid Ruby profilings.

[dylanahsmith]

Ok, sorry that I missed that. We should definitely add support for this in that case.

I was concerned that it exposed the liquid parse tree nodes, but it looks like the node objects it exposes are Liquid::Profiler::Timing nodes. So I think we should be able to support it without too much trouble.

[macournoyer]

This is causing issues now in the Theme Inspector w/ Core. For eg. this flamegrapg use to be 6 levels deep:

I'll try to carve out some time to fix this soon. But perhaps in the meantime we could disable Liquid::C for profiling requests?

[dylanahsmith]

But perhaps in the meantime we could disable Liquid::C for profiling requests?

I thought the problem was with liquid-c mostly being disabled when profiling liquid. That happens automatically (https://github.com/Shopify/liquid-c/blob/368792ecacd3c5cf5b1b70b7c476038c832572c8/lib/liquid/c.rb#L66)

I'm not sure what affected the depth of the flamegraph

[macournoyer]

Found the issue. It's because section rendering logic doesn't set the profile option in the ParseContext: https://github.com/Shopify/storefront-renderer/blob/master/app/liquid/theme_render_context.rb#L265-L269. I don't understand how come it use to work before. I assume it's the same issue on Core.