pixiv private isucon 2016 ��ά (4/5)
����������:
�������顢���褤�� ISUCON �餷���ʤäƤ��ޤ��衣
������ǧ
access.log
�ν��פϤ���ʴ����Ǥ���
Request by count 12317 GET /image/* 2797 GET / 1983 POST /login 1218 GET /posts/* 1029 GET /js/jquery-2.2.0.js 1029 GET /favicon.ico 1029 GET /js/jquery.timeago.js 1028 GET /css/style.css 1028 GET /js/jquery.timeago.ja.js 1028 GET /js/main.js 930 GET /@user 655 POST /register 654 GET /admin/banned 579 POST /comment 579 POST / 112 GET /login 83 GET /posts?max_created_at= 56 GET /logout 1 GET /initialize Request by total time 72.877 0.0260554165177 GET / 34.018 0.0365784946237 GET /@user 18.444 0.22221686747 GET /posts?max_created_at= 15.705 0.0271243523316 POST / 12.566 0.0103169129721 GET /posts/* 8.439 0.000685150604855 GET /image/* 5.644 0.00284619263742 POST /login 1.825 0.00278625954198 POST /register 1.661 0.00286873920553 POST /comment 1.648 0.00251987767584 GET /admin/banned 0.475 0.00424107142857 GET /login 0.45 0.00803571428571 GET /logout 0.026 0.026 GET /initialize
top �Ϥ���ʴ���
Tasks: 73 total, 1 running, 72 sleeping, 0 stopped, 0 zombie %Cpu(s): 55.4 us, 10.8 sy, 0.0 ni, 23.5 id, 3.1 wa, 0.0 hi, 6.7 si, 0.5 st KiB Mem: 1022972 total, 617428 used, 405544 free, 18260 buffers KiB Swap: 0 total, 0 used, 0 free. 314552 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1122 isucon 20 0 403944 68064 8328 S 76.3 6.7 0:16.87 app.f9aa6c7 731 mysql 20 0 993756 159744 10756 S 62.6 15.6 0:15.46 mysqld 1033 www-data 20 0 92024 5136 3056 S 7.0 0.5 0:01.63 nginx 1069 isucon 20 0 28796 6136 2636 S 2.7 0.6 0:00.80 tmux 308 memcache 20 0 330528 6060 2228 S 0.7 0.6 0:00.14 memcached
���������ꥯ�����ȿ��������Ƥ����Τȡ��ޤ����� idle ���ĤäƤ���Τǡ�ǰ�ΰ٥٥���ޡ���ľ��� netstat ���ǧ���Ƥ����ޤ���
$ netstat -tn ... tcp6 0 0 127.0.0.1:8080 127.0.0.1:63462 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:64494 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63477 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63563 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63877 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:64234 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63565 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:64008 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63594 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:64065 TIME_WAIT $ netstat -tn | grep -c TIME_WAIT 1981
�ޤ��ͤޤ�ۤɤ���ʤ����ɰ�� /etc/nginx/sites-enabled/isucon.conf
�� upstream �� keepalive �� 64 �����䤷�Ƥ����ޤ���
�ڡ�������å���
�ץ��ե�����򸫤Ƥߤޤ���
(pprof) top30 -cum 5.66s of 23.80s total (23.78%) Dropped 584 nodes (cum <= 0.12s) Showing top 30 nodes out of 326 (cum >= 3.55s) flat flat% sum% cum cum% 0 0% 0% 22.30s 93.70% runtime.goexit 0 0% 0% 19.44s 81.68% net/http.(*conn).serve 0.01s 0.042% 0.042% 18.79s 78.95% net/http.serverHandler.ServeHTTP 0 0% 0.042% 18.78s 78.91% net/http.(*ServeMux).ServeHTTP 0 0% 0.042% 18.76s 78.82% github.com/zenazn/goji/web.(*Mux).ServeHTTP 0 0% 0.042% 18.72s 78.66% github.com/zenazn/goji/web.(*cStack).ServeHTTP 0 0% 0.042% 18.72s 78.66% github.com/zenazn/goji/web/middleware.RequestID.func1 0 0% 0.042% 18.72s 78.66% net/http.HandlerFunc.ServeHTTP 0.01s 0.042% 0.084% 18.69s 78.53% github.com/zenazn/goji/web/middleware.Logger.func1 0 0% 0.084% 18.27s 76.76% github.com/zenazn/goji/web/middleware.Recoverer.func1 0 0% 0.084% 18.21s 76.51% github.com/zenazn/goji/web.(*mStack).newStack.func1 0 0% 0.084% 18.21s 76.51% github.com/zenazn/goji/web.(*router).route 0 0% 0.084% 18.21s 76.51% github.com/zenazn/goji/web/middleware.AutomaticOptions.func1 0.01s 0.042% 0.13% 14.43s 60.63% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC 0 0% 0.13% 12.63s 53.07% main.getIndex 0.07s 0.29% 0.42% 9.88s 41.51% main.makePosts 0.01s 0.042% 0.46% 6.89s 28.95% github.com/jmoiron/sqlx.(*DB).Get 0.01s 0.042% 0.5% 6.88s 28.91% github.com/jmoiron/sqlx.Get 0.03s 0.13% 0.63% 6.80s 28.57% database/sql.(*DB).Query 0.02s 0.084% 0.71% 6.77s 28.45% database/sql.(*DB).query 0.03s 0.13% 0.84% 6.43s 27.02% database/sql.(*DB).queryConn 0.06s 0.25% 1.09% 6.02s 25.29% github.com/go-sql-driver/mysql.(*mysqlConn).Query 0.02s 0.084% 1.18% 4.65s 19.54% github.com/jmoiron/sqlx.(*DB).QueryRowx 4.06s 17.06% 18.24% 4.38s 18.40% syscall.Syscall 1.17s 4.92% 23.15% 4.08s 17.14% runtime.mallocgc 0 0% 23.15% 3.83s 16.09% github.com/jmoiron/sqlx.(*DB).Select 0.01s 0.042% 23.19% 3.83s 16.09% github.com/jmoiron/sqlx.Select 0 0% 23.19% 3.72s 15.63% github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC 0.12s 0.5% 23.70% 3.58s 15.04% runtime.systemstack 0.02s 0.084% 23.78% 3.55s 14.92% syscall.Write (pprof) list getIndex Total: 23.80s ROUTINE ======================== main.getIndex in /home/isucon/private_isu/webapp/golang/app.go 0 12.63s (flat, cum) 53.07% of Total . . 413: . . 414: http.Redirect(w, r, "/", http.StatusFound) . . 415:} . . 416: . . 417:func getIndex(w http.ResponseWriter, r *http.Request) { . 330ms 418: me := getSessionUser(r) . . 419: . . 420: results := []Post{} . . 421: . 600ms 422: err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20") . . 423: if err != nil { . . 424: fmt.Println(err) . . 425: return . . 426: } . . 427: . 8.43s 428: posts, merr := makePosts(results, getCSRFToken(r), false) . . 429: if merr != nil { . . 430: fmt.Println(merr) . . 431: return . . 432: } . . 433: . . 434: fmap := template.FuncMap{ . . 435: "imageURL": imageURL, . . 436: } . . 437: . 40ms 438: template.Must(template.New("layout.html").Funcs(fmap).ParseFiles( . 10ms 439: getTemplPath("layout.html"), . 10ms 440: getTemplPath("index.html"), . . 441: getTemplPath("posts.html"), . . 442: getTemplPath("post.html"), . 1.20s 443: )).Execute(w, struct { . . 444: Posts []Post . . 445: Me User . . 446: CSRFToken string . . 447: Flash string . 2.01s 448: }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")}) . . 449:} . . 450: . . 451:func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) { . . 452: user := User{} . . 453: uerr := db.Get(&user, "SELECT * FROM `users` WHERE `account_name` = ? AND `del_flg` = 0", c.URLParams["accountName"])
�ƥ�ץ졼�Ȥ��Ϥ������ []Post
���Ѱդ��� makePosts
�ؿ������ֽŤ���ΤΡ��ǽ�� Post ������������� select �� 600ms, �ƥ�ץ졼�ȤΥ���ѥ���ȼ¹Ԥ�Â���� 3.2sec ����ޤ��͡�
�ƥ�ץ졼�ȤΥ���ѥ���ϵ�ư���˰��٤��Ф��������ʤΤ� 1.2sec ��̵�̤Ǥ���
�ޤ����ȥåץڡ�����ɽ����������Ƥϥ桼�����ˤ�����餺����ʤΤǡ�������󥰷�̤�ޤ뤴�ȥڡ�������å���Ǥ���С� makePosts �� 8.4sec �ȥƥ�ץ졼�ȤΥ�����󥰤� 2sec �ι�碌�� 10sec ��ܾۤä���뤳�Ȥ��Ǥ��ޤ���
�ڡ�������å��夬�¸��Ǥ��������ƥ�ץ졼�Ȥ���Ȥ��ǧ���Ƥߤ�ȡ��桼�������Ȥ˰ۤʤ����Ƥϡ� (1) �إå�����ʬ, (2) ���ե�����ˤ��� csrf token, �Ǥ�����������󥰤��Ť��Τϥݥ��Ȱ�������ʬ�Ǥ��礦���顢�إå����ϥڡ�������å�����оݳ��ˤ��ơ��ݥ��Ȱ�����ʬ�����ò¥¥ï¿½Ã¥ï¿½ï¿½å¤¹ï¿½ï¿½ï¿½ (1) �����ꤢ��ޤ�������� (2) �Ǥ�����������󥰻��˸���Υ�����ɤ�����ƥ�����󥰤��Ƥ������桼�������֤��Ȥ��������� csrf token ��ʸ�����ִ����뤳�Ȥˤ��ޤ���
�ڡ�������å�����륿���ߥ󥰤Ǥ����� getIndex()
���ƤФ줿���ˤ�����⡢�ȥåץڡ����˲����ѹ������ä��Ȥ� (��������Ƥ��줿�������Ȥ��줿���桼������������줿�ʤ�) �˥�����󥰤���ۤ�����ΨŪ�Ǥ���
����ˡ���ǽ���夬�äƤ���ȥȥåץڡ������ѹ�������ꥯ�����Ȥ����������ǽ��������Τǡ�������󥰤� Mutex ����¾���������ǡ� Mutex ���ԤäƤ� goroutine ��Ʊ����ʣ��¸�ߤ������Ϥ��Τ�����1�Ĥ�����������󥰤�����������Ѥ��ޤ�����
���������� GoCon 2016 Spring �� zero time cache �ѥ�����Ȥ��ƾҲ𤷤���Τǡ����Ƥ� POST �ꥯ�����Ȥ�������󥰤��ԤäƤ���쥹�ݥ󥹤��֤��Τǡ�����å���ˤ�빹����ȿ�Ǥ����ޤǤ��ٱ䤬¸�ߤ��ޤ���
diff --git a/app.go b/app.go index b5a8fac..f246ad6 100644 --- a/app.go +++ b/app.go @@ -1,6 +1,7 @@ package main import ( + "bytes" crand "crypto/rand" "crypto/sha512" "encoding/hex" @@ -109,6 +110,8 @@ func dbInitialize() { for _, sql := range sqls { db.Exec(sql) } + + renderIndexPosts() } func tryLogin(accountName, password string) *User { @@ -414,38 +410,85 @@ func getLogout(w http.ResponseWriter, r *http.Request) { http.Redirect(w, r, "/", http.StatusFound) } -func getIndex(w http.ResponseWriter, r *http.Request) { - me := getSessionUser(r) +var ( + indexTemplate *template.Template + postsTemplate *template.Template - results := []Post{} + indexPostsM sync.Mutex + indexPostsT time.Time + indexPostsRenderedM sync.RWMutex + indexPostsRendered []byte +) + +func init() { + fmap := template.FuncMap{ + "imageURL": imageURL, + } + indexTemplate = template.Must(template.New("layout.html").Funcs(fmap).ParseFiles( + getTemplPath("layout.html"), + getTemplPath("index.html"), + )) + + postsTemplate = template.Must(template.New("posts.html").Funcs(fmap).ParseFiles( + getTemplPath("posts.html"), + getTemplPath("post.html"), + )) +} + +func renderIndexPosts() { + now := time.Now() + indexPostsM.Lock() + defer indexPostsM.Unlock() + if indexPostsT.After(now) { + return + } + now = time.Now() + + results := []Post{} err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20") if err != nil { - fmt.Println(err) + log.Println(err) return } - posts, merr := makePosts(results, getCSRFToken(r), false) + posts, merr := makePosts(results, "[[[CSRFTOKEN]]]", false) if merr != nil { - fmt.Println(merr) + log.Println(merr) return } - fmap := template.FuncMap{ - "imageURL": imageURL, + var b bytes.Buffer + if err := postsTemplate.Execute(&b, posts); err != nil { + log.Println(err) + return } - template.Must(template.New("layout.html").Funcs(fmap).ParseFiles( - getTemplPath("layout.html"), - getTemplPath("index.html"), - getTemplPath("posts.html"), - getTemplPath("post.html"), - )).Execute(w, struct { - Posts []Post - Me User - CSRFToken string - Flash string - }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")}) + indexPostsT = now + indexPostsRenderedM.Lock() + indexPostsRendered = b.Bytes() + indexPostsRenderedM.Unlock() +} + +func getIndexPosts(csrf string) template.HTML { + indexPostsRenderedM.RLock() + t := bytes.Replace(indexPostsRendered, []byte("[[[CSRFTOKEN]]]"), []byte(csrf), -1) + indexPostsRenderedM.RUnlock() + return template.HTML(string(t)) +} + +func getIndex(w http.ResponseWriter, r *http.Request) { + me := getSessionUser(r) + csrf := getCSRFToken(r) + posts := getIndexPosts(csrf) + + indexTemplate.Execute(w, + map[string]interface{}{ + "Me": me, + "CSRFToken": csrf, + "Flash": getFlash(w, r, "notice"), + "Posts": posts}, + ) } func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) { @@ -708,8 +751,9 @@ func postIndex(w http.ResponseWriter, r *http.Request) { } tf.Close() copyImage(int(pid), tf.Name(), mime) + + renderIndexPosts() http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound) - return } func getImage(c web.C, w http.ResponseWriter, r *http.Request) { @@ -765,6 +809,7 @@ func postComment(w http.ResponseWriter, r *http.Request) { query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?)" db.Exec(query, postID, me.ID, r.FormValue("comment")) + renderIndexPosts() http.Redirect(w, r, fmt.Sprintf("/posts/%d", postID), http.StatusFound) } @@ -821,6 +866,7 @@ func postAdminBanned(w http.ResponseWriter, r *http.Request) { db.Exec(query, 1, id) } + renderIndexPosts() http.Redirect(w, r, "/admin/banned", http.StatusFound) } @@ -864,6 +910,15 @@ func main() { db.SetMaxIdleConns(8) defer db.Close() + for { + if db.Ping() == nil { + break + } + log.Println("waiting db...") + } + + renderIndexPosts() + go http.ListenAndServe(":3000", nil) goji.Get("/initialize", getInitialize) diff --git a/templates/index.html b/templates/index.html index 22ff9c2..8c2b639 100644 --- a/templates/index.html +++ b/templates/index.html @@ -19,7 +19,7 @@ </form> </div> -{{ template "posts.html" .Posts }} +{{ .Posts }} <div id="isu-post-more"> <button id="isu-post-more-btn">��äȸ���</button>
��¬
������:
{"pass":true,"score":39743,"success":32254,"fail":0,"messages":[]}
top:
Tasks: 77 total, 1 running, 76 sleeping, 0 stopped, 0 zombie %Cpu(s): 44.7 us, 8.3 sy, 0.0 ni, 35.3 id, 5.1 wa, 0.0 hi, 6.0 si, 0.5 st KiB Mem: 1022972 total, 961900 used, 61072 free, 23704 buffers KiB Swap: 0 total, 0 used, 0 free. 604328 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1337 isucon 20 0 207476 68192 8880 S 63.6 6.7 0:13.73 app.dc4a3eaa 731 mysql 20 0 1059292 181996 10552 S 45.6 17.8 1:49.68 mysqld 1033 www-data 20 0 92008 5092 3056 S 8.0 0.5 0:11.70 nginx 1069 isucon 20 0 32140 9332 2636 S 4.0 0.9 0:07.71 tmux 3 root 20 0 0 0 0 S 0.3 0.0 0:15.56 ksoftirqd/0 13 root 20 0 0 0 0 S 0.3 0.0 0:29.07 ksoftirqd/1 43 root 20 0 0 0 0 S 0.3 0.0 0:00.15 kworker/u30:1 308 memcache 20 0 332576 7896 2228 S 0.3 0.8 0:00.89 memcached 968 isucon 20 0 80656 3496 2656 S 0.3 0.3 0:00.28 sshd
CPU ��������ͷ��Ǥ��ޤ����͡��ɤ����̤ΤȤ����ˤ���ܥȥ�ͥå��򸫤Ĥ��ʤ��Ȥ����ޤ���
myprofiler:
34 SELECT * FROM `users` WHERE `id` = N 30 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC 23 SELECT * FROM `posts` WHERE `id` = N 19 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC 11 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N 10 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N 8 SELECT `id` FROM `posts` WHERE `user_id` = N 2 INSERT INTO `users` (`account_name`, `passhash`) VALUES (S,S) 1 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC 1 SELECT COUNT(*) AS count FROM `comments` WHERE `post_id` IN (...N)
user �� PK �Ǽ���������ʬ���Ť��ߤ����Ǥ���
access.log:
Request by count 12394 GET /image/* 4149 GET / 2791 POST /login 1395 GET /posts/* 1207 POST /register 1207 GET /admin/banned 1049 GET /@user 1021 GET /js/jquery-2.2.0.js 1021 GET /css/style.css 1021 GET /js/jquery.timeago.ja.js 1021 GET /favicon.ico 1021 GET /js/jquery.timeago.js 1021 GET /js/main.js 704 POST /comment 698 POST / 120 GET /login 77 GET /posts?max_created_at= 61 GET /logout 1 GET /initialize Request by total time 30.646 0.0292144899905 GET /@user 24.051 0.0344570200573 POST / 14.411 0.187155844156 GET /posts?max_created_at= 12.099 0.00867311827957 GET /posts/* 11.879 0.0168735795455 POST /comment 9.296 0.00224053988913 GET / 6.612 0.00236904335364 POST /login 3.355 0.00277961888981 POST /register 2.882 0.00023253187026 GET /image/* 2.21 0.00183098591549 GET /admin/banned 0.448 0.00373333333333 GET /login 0.443 0.00726229508197 GET /logout 0.038 0.038 GET /initialize Request by out bytes 3847419944 310426 GET /image/* 264074503 258643 GET /js/jquery-2.2.0.js 99628388 24012 GET / ...
GET /
�� 2.2msec �ޤ�®���ʤ�ޤ������ޤ�®�������;�ϤϤ��뤱�ɡ���� GET /@user
�ʤɤι�®������Ǥ��礦�͡�
�ޤȤ�
������: 4745 (�������) -> 32771 (����) -> 39743 (�ȥåץڡ����Υڡ�������å���)
�ܥȥ�ͥå���CPU�ʳ��˰ܤäƤ���Τǡ������������Ԥ����ۤɿ��Ӥޤ���Ǥ���������Ϥ��Υܥȥ�ͥå���Ĵ������褷�ޤ���
�ڡ�������å�������Ѥ��� zero time cache �ѥ������ Go �������ñ�˼¸��Ǥ����ΤʤΤǡ� prefork ���Υ��ץꥵ���С���Ȥ�¾�θ���ǤϤ���ä��񤷤��Ǥ��� (node.js �ʤ顢2�����ޥ���ʤ饷�󥰥�ץ������Ǵ�ĥ��뤫���Τ�ޤ���)
¾�θ���Ǥϡ����̤� getIndex �ǥڡ�������å��夷�ƥ٥������������褦�˥���å������¸���֤�Ĵ������Ȥ����Хå����饦��ɤ�ư���ǡ�������Ū�˥ڡ�������å������������褦�ˤ��ƥ٥�����̤�褦�ˤ��������ֳ֤�Ĵ������Ȥ��ä��������ISUCON�Ǥϰ���Ū���Ȼפ��ޤ���
������������� pixiv private isucon �Ǥϥ롼��� POST ���֤äƤ��餽�����Ƥ��̤� GET �ꥯ�����Ȥ�ȿ�Ǥ����ޤǤ�ͱͽ����������Ƥ��ʤ��Τǡ�Ĵ���Τ����ʣ����٥�������餻��ɬ�פ����뤫�⤷��ޤ��� (Go �䤷)
@methane