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.

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

Liquid profiler #3762

Merged
merged 2 commits into from Jun 16, 2015
Merged

Liquid profiler #3762

merged 2 commits into from Jun 16, 2015

Conversation

fw42
Copy link
Contributor

@fw42 fw42 commented Jun 5, 2015

This PR adds a --profile flag to Jekyll which generates a Liquid performance profile. I found this very helpful when trying to figure out why our site was so slow and which pages are the most worthwhile to optimize.

The output shows the number of times a certain file is being rendered and the total time it took to render that file (only the 50 worst offenders are shown).

Looks like this on the Jekyll site:

$ bundle exec jekyll build -s site --profile
Configuration file: site/_config.yml
            Source: site
       Destination: /home/vagrant/src/jekyll/_site
 Incremental build: enabled
      Generating...

                           Filename | Count | Total time
------------------------------------+-------+-----------
                 _layouts/docs.html |    31 |      1.339
_includes/docs_contents_mobile.html |    31 |      0.754
         _includes/docs_option.html |   186 |      0.708
       _includes/docs_contents.html |    31 |      0.518
                 _layouts/news.html |    37 |      0.491
             _includes/docs_ul.html |   186 |      0.480
       _includes/news_contents.html |    37 |      0.265
_includes/news_contents_mobile.html |    37 |      0.210
                    _docs/assets.md |     1 |      0.146
              _layouts/default.html |    70 |      0.135
           _includes/news_item.html |    66 |      0.053
                 _docs/datafiles.md |     1 |      0.051
             _docs/configuration.md |     1 |      0.050
              _includes/header.html |    70 |      0.049
         _includes/section_nav.html |    31 |      0.047
                   _docs/plugins.md |     1 |      0.038
   _includes/primary-nav-items.html |   140 |      0.032
                    news/index.html |     1 |      0.031
           news/releases/index.html |     1 |      0.029
    _docs/continuous-integration.md |     1 |      0.025
                   _docs/history.md |     1 |      0.023
                           feed.xml |     1 |      0.021
               _docs/collections.md |     1 |      0.020
                 _docs/templates.md |     1 |      0.019
                     _docs/posts.md |     1 |      0.018

                    done in 3.876 seconds.
 Auto-regeneration: disabled. Use --watch to enable.

Doesn't look very impressive on this small site that is already quite fast, but I found some nice improvements with this on our bigger site.

The code that pretty-prints the output is a little bit ugly. Suggestions welcome about how to improve it.

@parkr @envygeeks @alfredxing, do you think this is something that could be useful for people?

@csaunders FYI

@envygeeks
Copy link
Contributor

It's useful to me, I have several very huge sites that would benefit from this because I know they have some pain spots I just don't have time to figure them out in hand-to-hand combat. I'm definitely 👍

@fw42
Copy link
Contributor Author

fw42 commented Jun 5, 2015

One thing that is not ideal: I'm generating the profile every time, not just when the --profile flag is set (the flag just determines whether or not to print the results). Not sure if that's a big deal. I can rethink this if necessary.

@envygeeks
Copy link
Contributor

The question isn't whether it generates the profile every time it's whether that impacts build times with incremental regeneration. It would be a deal break if it did but that should be easy to resolve by just modifying the flag to either start it or not start it no?

@fw42
Copy link
Contributor Author

fw42 commented Jun 5, 2015

I don't expect this to have much overhead, really.. But I can look into it more if @parkr thinks that this is worthwhile.

@parkr
Copy link
Member

parkr commented Jun 5, 2015

I love everything about this idea.

@fw42
Copy link
Contributor Author

fw42 commented Jun 5, 2015

Any comments about the implementation?

@fw42
Copy link
Contributor Author

fw42 commented Jun 5, 2015

Would be helpful if you guys could run this on some of your sites to get some confidence in this working correctly.

@envygeeks
Copy link
Contributor

I won't be able to help with that for a day or so, busy working on other stuff :/

@doktorbro
Copy link
Member

I like the profiler. @fw42 could you please align the file names to the left?

Filename                            | Count | Total time
------------------------------------+-------+-----------
_layouts/docs.html                  |    31 |      1.339
_includes/docs_contents_mobile.html |    31 |      0.754
_includes/docs_option.html          |   186 |      0.708
_includes/docs_contents.html        |    31 |      0.518
_layouts/news.html                  |    37 |      0.491
_includes/docs_ul.html              |   186 |      0.480
news/index.html                     |     1 |      0.031
news/releases/index.html            |     1 |      0.029

@envygeeks
Copy link
Contributor

Gonna agree that the name on the left and everything else on the right is more readable.

@fw42
Copy link
Contributor Author

fw42 commented Jun 7, 2015

I made the filenames left-aligned, cleaned up the code a little bit, and added a very basic test.

I'm ok with this being merged now as is, assuming someone could confirm that this works as expected on their sites (I tried the Jekyll site and my own site so far).

@alfredxing
Copy link
Member

👍 This is great! It'll be super useful for users with larger sites.

@envygeeks
Copy link
Contributor

I'm loving it too, I just played with it for our sites and found a few bottlenecks. Left a few notes though.

@envygeeks envygeeks added the pending-feedback We are waiting for more info. label Jun 7, 2015
@fw42
Copy link
Contributor Author

fw42 commented Jun 7, 2015

Addressed your comments. Thanks for the feedback.

@fw42
Copy link
Contributor Author

fw42 commented Jun 7, 2015

Also added a counter for number of generated bytes of rendered output, looks like this now:

Filename                                               | Count |    Bytes | Total time
-------------------------------------------------------+-------+----------+-----------
_layouts/docs.html                                     |    31 |  930.61K |      2.248
_includes/docs_contents_mobile.html                    |    31 |  311.24K |      1.239
_includes/docs_option.html                             |   186 |  293.65K |      1.158
_includes/docs_contents.html                           |    31 |  201.98K |      0.879
_includes/docs_ul.html                                 |   186 |  193.23K |      0.806
...

In my experience, that number of bytes is usually a good indication of why things are slow (huge nested loops generating megabytes of whitespace, for example).

@pathawks
Copy link
Member

pathawks commented Jun 8, 2015

What does it mean when I see a post with /#excerpt?

_posts/example.html/#excerpt |     1 |    8.37K | 0.014
_posts/example.html          |     1 |    8.37K | 0.013

@envygeeks
Copy link
Contributor

What is the source of the page?

@pathawks
Copy link
Member

pathawks commented Jun 8, 2015

What is the source of the page?

Sorry, it's not public.

If I'm the only one seeing this, I can just chalk it up to some plugin doing strange things. It's just that the word excerpt does not appear anywhere in the site source.

@pathawks
Copy link
Member

pathawks commented Jun 8, 2015

Turns out, all posts seem to generate this, it just doesn't appear most of the time.

If you create a Jekyll site that has nothing but a post or two, each post will show up in the profiler twice, once with /#excerpt appended to the filename.

@fw42
Copy link
Contributor Author

fw42 commented Jun 8, 2015

Hm interesting. I have no idea what that is. Is that a Jekyll internal thing where it modifies the path or something? I can merge those two if that makes sense. Or does it make more sense to show them separately?

@envygeeks
Copy link
Contributor

There is the excerpt piece to the front-matter that's shipped to you isn't there?

@parkr
Copy link
Member

parkr commented Jun 8, 2015

@fw42 @pathawks By default, every post is given an excerpt. The default excerpt separator is \n\n. The Excerpt class overrides the Post#id and appends #excerpt.

@fw42
Copy link
Contributor Author

fw42 commented Jun 8, 2015

I don't understand why "#excerpt" appears as the filename though unless it's overwriting the Post's path as well or something like that. Anyway, should I merge those two or keep them as separate ones?

@parkr
Copy link
Member

parkr commented Jun 8, 2015

I don't understand why "#excerpt" appears as the filename though unless it's overwriting the Post's path as well or something like that.

We do that so you know it's the post's excerpt, not the excerpt itself. So for @pathawks's example, the excerpt is the entire post instead of just a snippet of it. That would be a red flag for me.

Anyway, should I merge those two or keep them as separate ones?

Keep them as separate, please!

@envygeeks
Copy link
Contributor

Are users penalized for not having an "excerpt" because none of my sites provide an excerpt because I have no use for them (because we take advantage of canonical urls and meta) to just post the full article and inform Google/Bing that this is just an alias of post.

@pathawks
Copy link
Member

pathawks commented Jun 9, 2015

Are users penalized for not having an "excerpt"

None of my posts have an excerpt, and none of my layouts try to use an excerpt. If Jekyll is really spending double the time for each post to generate the excerpt (once for example.html, once for example.html/#excerpt), I'd really like to be able to disable that.

But this is pretty far off topic, I suppose.

@fw42
Copy link
Contributor Author

fw42 commented Jun 16, 2015

Anything left to do here? Everybody happy with the code? Seems like a few people have tried this out on their site. Any problems so far?

@envygeeks envygeeks added :shipit: and removed pending-feedback We are waiting for more info. labels Jun 16, 2015
@envygeeks
Copy link
Contributor

👍

@envygeeks
Copy link
Contributor

:shipit: and lets get a new beta out so people can play with it in the real world.

def print_stats
if @config['profile']
puts @liquid_renderer.stats_table
end
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why not use a suffix if statement here?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Personally I think this way is more readable, even if it takes up 2 more lines. I do the same exact thing he did in methods like that. I only suffix the if when there are more lines to follow but if it's a boolean method like this on I will multi-line the boolean statement.

@parkr
Copy link
Member

parkr commented Jun 16, 2015

Eggcellent. 🥚

parkr added a commit that referenced this pull request Jun 16, 2015
@parkr parkr merged commit 8b44a7b into jekyll:master Jun 16, 2015
parkr added a commit that referenced this pull request Jun 16, 2015
@fw42
Copy link
Contributor Author

fw42 commented Jun 16, 2015

❤️

@doktorbro
Copy link
Member

doktorbro commented Jun 16, 2015 via email

@envygeeks
Copy link
Contributor

@penibelst if you don't want to wait you can use jekyll/master on Docker it already has the changes.

@doktorbro
Copy link
Member

doktorbro commented Jun 17, 2015 via email

@envygeeks
Copy link
Contributor

It seems to me that testing didn't point this out (I should have probably used it on a production site) but today when the new beta was released I ran into a problem, this seems to be passing data that was previously never passed?

Configuration file: /srv/jekyll/_config.yml
            Source: /srv/jekyll
       Destination: /srv/jekyll/_site
 Incremental build: enabled
      Generating... 
  Conversion error: Content::Pipeline::Jekyll::Converter encountered an error while converting '_posts/2012-11-17-dear-heroku-fuck-your-bullshit-toolbelt.md/#excerpt':
                    undefined method `gsub' for nil:NilClass
/srv/jekyll/vendor/bundle/ruby/2.2.0/gems/content-pipeline-2.2.1/lib/content/pipeline/jekyll/converter.rb:23:in `convert': undefined method `gsub' for nil:NilClass (NoMethodError)
    from /srv/jekyll/vendor/bundle/ruby/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/convertible.rb:73:in `block in transform'
    from /srv/jekyll/vendor/bundle/ruby/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/convertible.rb:71:in `each'
    from /srv/jekyll/vendor/bundle/ruby/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/convertible.rb:71:in `reduce'
    from /srv/jekyll/vendor/bundle/ruby/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/convertible.rb:71:in `transform'
    from /srv/jekyll/vendor/bundle/ruby/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/convertible.rb:247:in `do_layout'
    from /srv/jekyll/vendor/bundle/ruby/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/post.rb:270:in `render'
    from /srv/jekyll/vendor/bundle/ruby/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/site.rb:180:in `block in render'
    from /srv/jekyll/vendor/bundle/ruby/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/site.rb:178:in `each'
    from /srv/jekyll/vendor/bundle/ruby/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/site.rb:178:in `render'
    from /srv/jekyll/vendor/bundle/ruby/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/site.rb:59:in `process'
    from /usr/lib/ruby/gems/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/command.rb:28:in `process_site'
    from /usr/lib/ruby/gems/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/commands/build.rb:60:in `build'
    from /usr/lib/ruby/gems/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/commands/build.rb:35:in `process'
    from /usr/lib/ruby/gems/2.2.0/gems/jekyll-3.0.0.pre.beta7/lib/jekyll/commands/serve.rb:26:in `block (2 levels) in init_with_program'
    from /usr/lib/ruby/gems/2.2.0/gems/mercenary-0.3.5/lib/mercenary/command.rb:220:in `call'
    from /usr/lib/ruby/gems/2.2.0/gems/mercenary-0.3.5/lib/mercenary/command.rb:220:in `block in execute'
    from /usr/lib/ruby/gems/2.2.0/gems/mercenary-0.3.5/lib/mercenary/command.rb:220:in `each'
    from /usr/lib/ruby/gems/2.2.0/gems/mercenary-0.3.5/lib/mercenary/command.rb:220:in `execute'
    from /usr/lib/ruby/gems/2.2.0/gems/mercenary-0.3.5/lib/mercenary/program.rb:42:in `go'
    from /usr/lib/ruby/gems/2.2.0/gems/mercenary-0.3.5/lib/mercenary.rb:19:in `program'
    from /usr/lib/ruby/gems/2.2.0/gems/jekyll-3.0.0.pre.beta7/bin/jekyll:17:in `<top (required)>'
    from /usr/local/bin/jekyll:23:in `load'
    from /usr/local/bin/jekyll:23:in `<main>'

And the source of that file: https://github.com/envygeeks/ruby-content-pipeline/blob/master/lib/content/pipeline/jekyll/converter.rb

/cc @fw42 @parkr

@envygeeks
Copy link
Contributor

Nevermind, I blamed my site and that file and it turns out this is not to blame, somebody adjust data.

@naifaborzg
Copy link

Sent from Yahoo Mail on Android

From :"Pat Hawks" < notifications@github.com >
Date :الاثنين, يونيو ٨, ٢٠١٥ at ٦:٠٦ ص
Subject :Re: [jekyll] Liquid profiler (#3762)
What does it mean when I see a post with /#excerpt?
_posts/example.html/#excerpt |     1 |    8.37K | 0.014
_posts/example.html          |     1 |    8.37K | 0.013

Reply to this email directly or  view it on GitHub .

@jekyll jekyll locked and limited conversation to collaborators Nov 5, 2015
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

8 participants