• From: Wilhelmsburg
  • Registered: 2008-10-02
  • Posts: 23

Topic: Log file analysis

Hello,

could anybody tell me something about the following part of my log file?

Rendered categories/_options (0.01718)
  Topic Load (0.000233)   SELECT * FROM `topics` WHERE (category_id = 1) ORDER BY last_post_id DESC LIMIT 1
  CACHE (0.000000)   SELECT * FROM `topics` WHERE (category_id = 1) ORDER BY last_post_id DESC LIMIT 1
  Topic Columns (0.001730)   SHOW FIELDS FROM `topics`
  Post Load (0.000185)   SELECT * FROM `posts` WHERE (topic_id = 3338) ORDER BY posts.id DESC LIMIT 1
  Post Columns (0.001362)   SHOW FIELDS FROM `posts`
  CACHE (0.000000)   SELECT * FROM `topics` WHERE (category_id = 1) ORDER BY last_post_id DESC LIMIT 1
  CACHE (0.000000)   SELECT * FROM `topics` WHERE (category_id = 1) ORDER BY last_post_id DESC LIMIT 1
  SQL (0.000180)   SELECT count(*) AS count_all FROM `posts` WHERE (`posts`.topic_id = 3338) 
  CACHE (0.000000)   SELECT * FROM `topics` WHERE (category_id = 1) ORDER BY last_post_id DESC LIMIT 1
  Post Load (0.000132)   SELECT * FROM `posts` WHERE (`posts`.topic_id = 3338) ORDER BY posts.id DESC LIMIT 1
Rendered categories/_category (0.22172)

I mean what exactly does Topic Load and Post Load mean?
And how many queries are executed for this partial at all?
What does CACHE mean ... MySQL Query Cache?

How to analyse the entire log file? Are there any good tools for Linux?

cheers,

oerdec

  • From: Vienna, Austria
  • Registered: 2009-01-26
  • Posts: 27

Re: Log file analysis

Hi oerdec,

Great you bring this topic up. I once worked in a company where the default environment.rb didn't show the log at all, and I guess it was just because the were bored by long lines of output they didn't understand.

First of all: The less lines per reuqest the better. If you see lines that basically repeat, maybe only some id being different, then you have a problem and should think about eager loading or different optimizations.

In your case you have four database queries, one on topics, three on posts of which one is a find_by_sql or count_by_sql ? That's bad.

These two lines are almost the same, please check all you find calls and remove the differences so you have one query less:

Post Load (0.000185)   SELECT * FROM `posts` WHERE (topic_id = 3338) ORDER BY posts.id DESC LIMIT 1
Post Load (0.000132)   SELECT * FROM `posts` WHERE (`posts`.topic_id = 3338) ORDER BY posts.id DESC LIMIT

Do you know about counter caches? They are awesome and if you are in the index view and print out each topic with the number of posts then a counter cache will save you a lot of queries.  
SQL (0.000180)   SELECT count(*) AS count_all FROM `posts` WHERE (`posts`.topic_id = 3338)

About analyzing tools: They are useful to find out in production mode which actions are called often. I look at what the longest taking requests are. grep and sort -nr are your friend, the log is your enemy ;-) But at the end, the trick is just understanding the log, sorry about.

If you have a few lines of log from the index call, please post it.

PS: The 'Post Columns' lines are because of development mode and will go away in production.

Last edited by TomK32 (2009-01-30 05:25:11)

Ruby on Rails developer from Vienna looking for freelance gigs. My Blog. If I answered your questions I'd be happy if you recommend me at working-with-rails

TomK32's Website

  • From: Wilhelmsburg
  • Registered: 2008-10-02
  • Posts: 23

Re: Log file analysis

Thank you for your response, Tom. In the next couple of days or weeks I'm going to optimise my application. I will concentrate on every XXX Load entry per request. Maybe that's a good exercise in grep and sort, too. At the moment they aren't my friends wink

BTW - I know that counter cache technique. I'm already using it for num posts per topic and num posts per category and so on. But maybe I can use it much more. I will check this.

Cheers

oerdec