Measuring Execution Time of Liquid Code Fragments (time_diff)

Last edit: Jul 09, 2019
  • Contributors:
  • diana-lakatos
  • pavelloz

This guide will help you measure the execution time of Liquid code fragments using the time_diff filter. You can use this quick and simple method to find out which part of a page is slow.

Requirements

This is an advanced tutorial. To follow it, you should be familiar with basic platformOS concepts, the topics in the Get Started section, the time_diff and to_time Liquid filters, and how to create application logs.

Steps

Measuring the execution time of Liquid code fragments using the time_diff Liquid filter is a three-step process:

  1. Identify measuring points
  2. Add to_time and time_diff filters
  3. See results in logs

Step 1: Identify measuring points

Assuming there is a problem somewhere, you have to decide which parts to measure. Take a look at this sample snippet.


{% graphql g = 'modules/n_plus_one/n1_programmers' %}

{% for programmer in g.programmers.results %}
  <tr>
    <td>{{ programmer.properties.email }}</td>
    <td>{{ programmer.properties.title }}</td>
    <td>{{ programmer.company.properties.name }}</td>
  </tr>
{% endfor %}

There are two suspicious parts that could cause the results to be displayed slowly:

  1. GraphQL query
  2. for loop rendering records

Step 2: Add to_time and time_diff filters

Use the to_time and time_diff filters to measure execution times.
The graph_duration and render_duration variables store partial execution times in milliseconds. The total_duration variable stores the overall execution time of the code block.


{% assign __start = "now" | to_time %}

{% graphql g = 'modules/n_plus_one/programmers' %}

{% assign __graph = "now" | to_time %}

{% for programmer in g.programmers.results %}
  <tr>
    <td>{{ programmer.properties.email }}</td>
    <td>{{ programmer.properties.title }}</td>
    <td>{{ programmer.company.properties.name }}</td>
  </tr>
{% endfor %}

{% assign __render = "now" | to_time %}

{% assign _total_duration = __start | time_diff: __render %}
{% assign _graph_duration = __start | time_diff: __graph %}
{% assign _render_duration = __graph | time_diff: __render %}

{% log _total_duration, type: "benchmark-total" %}
{% log _graph_duration, type: "benchmark-graph" %}
{% log _render_duration, type: "benchmark-render" %}

Step 3: See results in logs

Test results are sent to your instance log stream and can be accessed by using the
pos-cli logs tool.

Live example and source code

To see how it works on a real webpage go to the live example page.
Source code can be found on GitHub.

Next steps

Congratulations! You know how to measure the execution time of Liquid code fragments using the time_diff filter. Check out another tutorial that uses this method for testing two different solutions.

Questions?

We are always happy to help with any questions you may have.