博客系统首页加载慢,分析及优化

/ 运维转载 / 没有评论 / 188浏览

原博作者的分析过程,值得一看~


背景 自己在阿里云上搭建了一个个人 Blog,用的是开源的 Tale,一个 Java 开发的支持 Markdown 博客。一直用着都挺好的,直到有一天我发现首页加载出奇的慢,平均要17、18秒的样子。然后其他文章页面却比较正常,也就1、2秒的样子。

问题定位 前端排查 因为一直以来我就只更改了部分前端的内容,后端 Java 代码根本就没动过,首先怀疑是不是前端什么 JS 资源被我改坏了,一直要等待超时才能响应。 通过 Chrome 开发者工具调试观察,并没有发现什么问题。 还好我用 Git 管理源码,不管三七二十一直接还原到最初的版本,重新部署发现问题依旧,一下子陷入懵逼。 201951395253-blog-index-slow-load

Nginx 排查 做了以上前端排查后,怀疑是是不是 Nginx 有缓存,强制清理缓存后发现问题依旧。 CURL 辅助排查 经过以上排查,我逐渐把排查的方向转移到后端。 使用 curl 直接在内网请求首页,发现依旧很慢,这基本排除不可能是前端或 JS等静态资源的问题,因为我是直接把请求内容保存到文本文件的。前端脚本什么的都不会渲染。为了统计 CURL 请求的时间,定制了一下请求参数,保存在 curl-format.txt 文件:

time_namelookup:  %{time_namelookup}\n
    time_connect:  %{time_connect}\n
 time_appconnect:  %{time_appconnect}\n
time_pretransfer:  %{time_pretransfer}\n
   time_redirect:  %{time_redirect}\n
time_starttransfer:  %{time_starttransfer}\n
                 ----------\n
      time_total:  %{time_total}\n

一次完整的请求如下:

$ curl -w "@curl-format.txt" -o /dev/null -s "http://127.0.0.1:9000"
    time_namelookup:  0.001
       time_connect:  0.001
    time_appconnect:  0.000
   time_pretransfer:  0.001
      time_redirect:  0.000
 time_starttransfer:  16.760
                    ----------
         time_total:  16.760

经过上面的排查我基本确定,问题应该出现在后端 后端排查 因为我使用 tale 默认的工具 tool 管理博客进程,看了一下默认启动默认分配 256M 的内存

停止

./tool stop

启动

./ tool start

启动后看到的情况

java -Xms256m -Xmx256m -Dfile.encoding=UTF-8 -jar tale-latest.jar --app.env=prod top 命令辅助排除 使用 top 命令辅助排查内存和 CPU,不查不知道,一查吓一跳,当请求首页的时候,CPU 飙升到接近 100%

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 10815 zhanga 20 0 2406m 225m 13m S 99.2 16.7 22:22.87 java 29864 root 20 0 2005m 74m 3244 S 0.3 7.5 3077:37 java 26135 root 0 -20 123m 8480 5628 S 0.3 0.8 107:22.87 AliYunDun
一瞬间怀疑是不是遭受 DDOS 攻击了,但是除了首页其他页面都正常,基本可以排除了,几百兆内存跑起来的博客也有人攻击那就太没天理了。 于是怀疑是内存给小了,是不是引起频繁 GC 导致 CPU 飙升的 基于以上怀疑自己写启动脚本调大内存配置至 400M,并记录 GC 日志

新的启动脚本

nohup java -Xms400m -Xmx400m -verbose:gc -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -Dfile.encoding=UTF-8 -jar tale-latest.jar --app.env=prod > tale.log 2>&1 &
echo "$!" > pid
2019-05-13T10:17:10.902+0800: 37622.895: [GC (Allocation Failure) 2019-05-13T10:17:10.902+0800: 37622.895: [DefNew: 109585K->282K(122880K), 0.0020507 secs] 117507K->8205K(395968K), 0.0021385 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2019-05-13T10:21:43.112+0800: 37895.104: [GC (Allocation Failure) 2019-05-13T10:21:43.112+0800: 37895.104: [DefNew: 109530K->268K(122880K), 0.0018163 secs] 117453K->8191K(395968K), 0.0018836 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

分析一下上面的 GC 日志:

首先每次请求都会有一两条如上的 GC 日志,Allocation Failure 表示向 Young generation(eden)给新对象申请空间。简单来讲不是 Full GC 并且 GC 的时间很快,对系统性能影响有限。 下面对整个第一条 GC 日志做个详细的分析:

2019-05-13T10:17:10.902+0800 代表 GC 日志开始的时间点
37622.895 GC 事件的开始时间,相对于 JVM 的启动时间,单位是秒
GC 用来区分(distinguish)是 Minor GC 还是 Full GC 的标志(Flag). 这里的 GC 表明本次发生的是 Minor GC
Allocation Failure 引起垃圾回收的原因. 本次 GC 是因为年轻代中(Young Generation)没有任何合适的区域能够存放需要分配的数据结构而触发的
DefNew 使用的垃圾收集器的名字,DefNew 这个名字代表的是: 单线程(single-threaded), 采用标记复制(mark-copy)算法的, 使整个 JVM 暂停运行(stop-the-world)的年轻代(Young generation) 垃圾收集器(garbage collector)
109585K->282K 在本次垃圾收集之前和之后的年轻代内存使用情况(Usage)
122880K 年轻代的总的大小(Total size)
117507K->8205K 本次垃圾收集之前和之后整个堆内存的使用情况(Total used heap)
395968K 总的可用的堆内存(Total available heap).
0.0021385 secs GC事件的持续时间(Duration),单位是秒
Times user 此次垃圾回收, 垃圾收集线程消耗的所有CPU时间(Total CPU time)
sys 操作系统调用(OS call) 以及等待系统事件的时间(waiting for system event)
real 应用程序暂停的时间(Clock time). 由于串行垃圾收集器(Serial Garbage Collector)只会使用单个线程, 所以 real time 等于 user 以及 system time 的总和

通过上面分析可以计算出:

在垃圾收集之前,堆内存总的使用了 117507K 内存。其中, 年轻代使用了 109585K,可以算出老年代使用的内存为: 117507K - 109585K = 7922K。 年轻代在经过垃圾回收后由 109585K 减少到 282K,下降了 109303K。总堆栈由 117507K 减少到 8205K,下降了 109302K,通过这一点我们可以计算出有 109303K - 109302K = 1K 的年轻代对象被提升到老年代(Old)中。 以上年轻代内存回收比例比较大,大概率大部分被回收的是缓存的内容,以上分析权当父复习一下 GC 的相关内容。 大致过程可展示为如下:、

GC

罗里吧嗦分析了这么多,很明显问题也不是出在 GC 上,但 CPU 飙高,事出反常必有妖,还有待继续追踪。

定位高CUP占用 查看博客进程

$ jps -ml 18731 sun.tools.jps.Jps -ml 10815 tale-latest.jar --app.env=prod 监控进程所有线程,访问首页触发高 CPU 占用

触发高CPU占用

curl -w "@curl-format.txt" -o /dev/null -s "http://127.0.0.1:9000"

监控所有线程

top -n 1 -H -p 10815

同时用 jstack 记录堆栈信息

jstack 10815 > jstack-output.txt 线程监控结果

Tasks:  20 total,   1 running,  19 sleeping,   0 stopped,   0 zombie
Cpu(s):  4.3%us,  1.1%sy,  0.0%ni, 94.6%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   1019988k total,   781700k used,   238288k free,    83848k buffers
Swap:        0k total,        0k used,        0k free,   283120k cached
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                
10838 zhanga    20   0 2407m 228m  13m R 97.8 23.0  22:57.07 java                                            10815 zhanga    20   0 2407m 228m  13m S  0.0 23.0   0:00.00 java                                            10816 zhanga    20   0 2407m 228m  13m S  0.0 23.0   0:00.29 java                                            10817 zhanga    20   0 2407m 228m  13m S  0.0 23.0   0:03.45 java                                            10818 zhanga    20   0 2407m 228m  13m S  0.0 23.0   0:00.00 java                                            10819 zhanga    20   0 2407m 228m  13m S  0.0 23.0   0:00.15 java                                            10820 zhanga    20   0 2407m 228m  13m S  0.0 23.0   0:00.00 java  

可以看到线程 ID 为 10838 占用了所有 CPU,把 PID 转为 16 进制

十进制 十六进制 10838 2a56 查看 jstack-output.txt 搜索关键词 2a56

"worker@threadㄧ1" #18 prio=5 os_prio=0 tid=0x00007fd8d4009000 nid=0x2a56 runnable [0x00007fd8dd284000]
   java.lang.Thread.State: RUNNABLE
        at java.util.regex.Pattern$BnM.match(Pattern.java:5464)
        at java.util.regex.Matcher.search(Matcher.java:1248)
        at java.util.regex.Matcher.find(Matcher.java:637)
        at java.util.regex.Matcher.replaceAll(Matcher.java:951)
        at java.lang.String.replace(String.java:2240)
        at com.vdurmont.emoji.EmojiParser.parseToUnicode(EmojiParser.java:129)
        at com.tale.extension.Commons.emoji(Commons.java:240)
        at com.tale.utils.TaleUtils.mdToHtml(TaleUtils.java:170)
        at com.tale.extension.Theme.intro(Theme.java:299)
        at com.tale.extension.Theme.intro(Theme.java:281)
        at sun.reflect.GeneratedMethodAccessor108.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

分析如上调用堆栈,发现正则匹配相关逻辑,很可疑 还好博客是开源的,定位到源码 com.tale.utils.TaleUtils.mdToHtml 这个方法,从名字可知是 Markdown 转 HTML 的功能 于是不加思索,埋点统计一下执行时间,代码如下:

public static String mdToHtml(String markdown) {
        long start = System.currentTimeMillis();
        if (StringKit.isBlank(markdown)) {
            return "";
        }

        List<Extension> extensions = Arrays.asList(TablesExtension.create());
        Parser          parser     = Parser.builder().extensions(extensions).build();
        Node            document   = parser.parse(markdown);
        HtmlRenderer renderer = HtmlRenderer.builder()
                .attributeProviderFactory(context -> new LinkAttributeProvider())
                .extensions(extensions).build();

        String content = renderer.render(document);
        content = Commons.emoji(content);

        ......

        log.error("mdToHtml millis:" + (System.currentTimeMillis() - start));
        return content;
    }

编译打包部署重启,请求首页 log 如下:

2019/05/13 23:23:10 DEBUG [   worker@threadㄧ1 ]                       o.s.Query : Execute SQL => SELECT * FROM t_contents WHERE type = ? AND status = ? ORDER BY created DESC LIMIT 0,12
2019/05/13 23:23:10 DEBUG [   worker@threadㄧ1 ]                       o.s.Query : Parameters  => [post, publish]
2019/05/13 23:23:10 DEBUG [   worker@threadㄧ1 ]                       o.s.Query : Total       => 6 ms, execution: 1 ms, reading and parsing: 5 ms; executed [null]
2019/05/13 23:23:10 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:56
2019/05/13 23:23:10 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:55
2019/05/13 23:23:10 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:55
2019/05/13 23:23:11 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:482
2019/05/13 23:23:11 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:506
2019/05/13 23:23:12 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:481
2019/05/13 23:23:12 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:68
2019/05/13 23:23:12 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:68
2019/05/13 23:23:12 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:68
2019/05/13 23:23:12 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:29
2019/05/13 23:23:12 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:28
2019/05/13 23:23:12 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:28
2019/05/13 23:23:12 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:36
2019/05/13 23:23:12 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:33
2019/05/13 23:23:12 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:35
2019/05/13 23:23:12 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:31
2019/05/13 23:23:12 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:30
2019/05/13 23:23:12 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:32
2019/05/13 23:23:13 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:679
2019/05/13 23:23:14 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:684
2019/05/13 23:23:15 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:996
2019/05/13 23:23:15 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:44
2019/05/13 23:23:15 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:42
2019/05/13 23:23:15 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:44
2019/05/13 23:23:16 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:1089
2019/05/13 23:23:17 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:1044
2019/05/13 23:23:18 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:1079
2019/05/13 23:23:18 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:330
2019/05/13 23:23:19 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:327
2019/05/13 23:23:19 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:327
2019/05/13 23:23:21 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:1559
2019/05/13 23:23:22 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:1527
2019/05/13 23:23:24 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:1558
2019/05/13 23:23:24 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:689
2019/05/13 23:23:25 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:680
2019/05/13 23:23:26 ERROR [   worker@threadㄧ1 ]                 c.t.u.TaleUtils : mdToHtml millis:688
2019/05/13 23:23:26 DEBUG [   worker@threadㄧ1 ]                       o.s.Query : Execute SQL => SELECT COUNT(*) FROM t_contents WHERE type = ? AND status = ?
2019/05

终于真相大白了

结论 每次进首页的时候都会加载 36 条记录,也就是是 36 片博客,然后把 Markdown 转为 HTML,有些博文很长,加上阿里云本身 1G、1核、1M 带宽的配置。 这也解释了为什么首页会慢,单个博客就不是很慢的原因。 按理说有缓存的话也就慢一次,后面都会很快,难道是缓存没生效,还是缓存每次都被 GC 释放了呢,后面再做详细调查 从后台日志来看目前每刷新一次都会查询数据库,都会 调用 mdToHtml 转换一次,查数据库本省时间不太长,主要时间还是花在了 mdToHtml 方法上;

原博主地址