Instantly share code, notes, and snippets.

Embed
What would you like to do?
[isucon@ip-172-31-9-240 go]$ grep query log | lltsv -k sum,count,mean,query -K | sort -n -r
42.515819 411 0.103445 SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT ? OFFSET ?
29.318021 836 0.035069 SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=? ORDER BY created_at
23.003601 830 0.027715 SELECT count(*) AS c FROM memos WHERE is_private=0
19.085289 419 0.045550 SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT ?
6.244089 170 0.036730 SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=? ORDER BY created_at DESC
6.204839 158 0.039271 SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=? AND is_private=0 ORDER BY created_at
0.702008 1303 0.000683 SELECT * FROM users WHERE id=?
0.636161 1085 0.000619 SELECT id, user, content, is_private, created_at, updated_at FROM memos WHERE id=?
0.260924 83994 0.000254 SELECT username FROM users WHERE id=?
0.125518 170 0.000738 SELECT id, username, password, salt FROM users WHERE username=?
0.119622 170 0.000704 UPDATE users SET last_access=now() WHERE id=?
0.101019 170 0.000594 INSERT INTO memos (user, content, is_private, created_at) VALUES (?, ?, ?, now())
[isucon@ip-172-31-9-240 go]$ grep handler log | lltsv -k sum,count,mean,handler -K | sort -n -r
112.595701 1085 0.109529 memoHandler
71.088976 411 0.172966 recentHandler
49.193846 419 0.117408 topHandler
10.577193 170 0.062219 mypageHandler
0.489704 170 0.002881 memoPostHandler
0.473548 170 0.002786 signinPostHandler
0.320596 5464 0.000312 public
0.281419 170 0.001655 signoutHandler
0.094454 170 0.000556 signinHandler
[isucon@ip-172-31-9-240 go]$ grep template log | lltsv -k sum,count,mean,base -K | sort -n -r
75.879037 994 0.076337 memo
8.848884 830 0.010661 index
2.688126 170 0.015813 mypage
0.060962 170 0.000359 signin
@sonots

This comment has been minimized.

Owner

sonots commented Sep 23, 2014

Get stats from /var/log/nginx/access.log

stat.rb

require 'uri'
stats = {}
STDIN.readlines.each do |line|
  uri, reqtime = line.split("\t")
  path = uri.split('?').first
  reqtime = reqtime.to_f
  stat = stats[path] ||= { :count => 0, :sum => 0, :min => 0, :max => 0}
  stat[:sum] += reqtime
  stat[:max] = [stat[:max], reqtime].max
  stat[:min] = [stat[:min], reqtime].min
  stat[:count] += 1
end

stats.each do |path, val|
  val[:mean] = val[:sum] / val[:count].to_f
  out = { :path => path }.merge(val)
  puts out.map {|key, v| "#{key}:#{v}" }.join("\t")
end
$ cat /var/log/nginx/access.log | lltsv -k uri,reqtime -K | ruby stat.rb
path:/cgi-bin/php   count:1 sum:0.258   min:0   max:0.258   mean:0.258
path:/cgi-bin/php5  count:1 sum:0.265   min:0   max:0.265   mean:0.265
path:/cgi-bin/php-cgi   count:1 sum:0.261   min:0   max:0.261   mean:0.261
path:/cgi-bin/php.cgi   count:1 sum:0.26    min:0   max:0.26    mean:0.26
path:/cgi-bin/php4  count:1 sum:0.263   min:0   max:0.263   mean:0.263
path:/  count:2 sum:0.647   min:0   max:0.5 mean:0.3235
path:/clientaccesspolicy.xml    count:1 sum:0.159   min:0   max:0.159   mean:0.159
path:/foo/bar   count:1 sum:0.002   min:0   max:0.002   mean:0.002
cat /var/log/nginx/access.log | lltsv -k uri,reqtime -K | ruby stat.rb  | lltsv -k sum,count,mean,path -K | sort -n -r
0.647   2   0.3235  /
0.265   1   0.265   /cgi-bin/php5
0.263   1   0.263   /cgi-bin/php4
0.261   1   0.261   /cgi-bin/php-cgi
0.26    1   0.26    /cgi-bin/php.cgi
0.258   1   0.258   /cgi-bin/php
0.159   1   0.159   /clientaccesspolicy.xml
0.002   1   0.002   /foo/bar
@sonots

This comment has been minimized.

Owner

sonots commented Sep 23, 2014

Get stats from slow query log

$ mysqldumpslow -s t /var/lib/mysql/slow.log                                                                                            [23/1942]
Reading mysql slow query log from /var/lib/mysql/slow.log
Count: 697  Time=0.06s (39s)  Lock=0.00s (0s)  Rows=100.0 (69700), isucon[isucon]@localhost
  SELECT * FROM memos WHERE is_private=N ORDER BY created_at DESC, id DESC LIMIT N OFFSET N

Count: 1245  Time=0.02s (24s)  Lock=0.00s (0s)  Rows=104.9 (130601), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N  ORDER BY created_at

Count: 1273  Time=0.02s (21s)  Lock=0.00s (0s)  Rows=1.0 (1273), isucon[isucon]@localhost
  SELECT count(*) AS c FROM memos WHERE is_private=N

Count: 576  Time=0.02s (12s)  Lock=0.00s (0s)  Rows=100.0 (57600), isucon[isucon]@localhost
  SELECT * FROM memos WHERE is_private=N ORDER BY created_at DESC, id DESC LIMIT N

Count: 128789  Time=0.00s (6s)  Lock=0.00s (2s)  Rows=1.0 (128789), isucon[isucon]@localhost
  SELECT username FROM users WHERE id=N

Count: 244  Time=0.02s (5s)  Lock=0.00s (0s)  Rows=54.2 (13220), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N AND is_private=N ORDER BY created_at

Count: 227  Time=0.02s (4s)  Lock=0.00s (0s)  Rows=106.0 (24052), isucon[isucon]@localhost
  SELECT id, content, is_private, created_at, updated_at FROM memos WHERE user=N ORDER BY created_at DESC

Count: 19838  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=15.2 (301649), isucon[isucon]@localhost
  #

Count: 1893  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1893), isucon[isucon]@localhost
  SELECT * FROM users WHERE id=N

Count: 1594  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1594), isucon[isucon]@localhost
  SELECT id, user, content, is_private, created_at, updated_at FROM memos WHERE id='S'

Count: 227  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  UPDATE users SET last_access=now() WHERE id=N

Count: 227  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  INSERT INTO memos (user, content, is_private, created_at) VALUES (N, 'S', N, now())

Count: 227  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (227), isucon[isucon]@localhost
  SELECT id, username, password, salt FROM users WHERE username='S'

Count: 19  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (19), isucon[isucon]@localhost
  SELECT @@max_allowed_packet

Count: 20  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  SET NAMES utf8

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  # Time: N N:N:N
  # User@Host: isucon[isucon] @ localhost [N.N.N.N]  Id:     N
  # Query_time: N.N  Lock_time: N.N Rows_sent: N  Rows_examined: N
  SET timestamp=N;
  SELECT @@max_allowed_packet

Count: 9919  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Close stmt

Count: 9919  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Prepare
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment