诡异的博客首页慢加载排查

/ 技术Java / 2 条评论 / 302浏览

背景

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

问题定位

前端排查

201951395253-blog-index-slow-load

Nginx 排查

CURL 辅助排查

    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                                      
# 新的启动脚本
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 日志做个详细的分析:

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

  1. 在垃圾收集之前,堆内存总的使用了 117507K 内存。其中, 年轻代使用了 109585K,可以算出老年代使用的内存为: 117507K - 109585K = 7922K
  2. 年轻代在经过垃圾回收后由 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                                            

可以看到线程 ID10838 占用了所有 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)
    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;
    }
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

终于真相大白了

结论

  1. 来学习排查问题得思路了,非常棒。 不过我觉得解决这个问题应该是在保存文章时就转一下,下次直接访问转化后的html,避免每次访问都mktohtml,个人愚见。

    回复
    1. @暴走的程序猿

      数据库保存的是MD,如果直接转成HTML保存,你再次编辑的时候就变成编辑HTML了,恐怕你要懵逼了。除非同时保存MD和HTML,这样维护MD和HTML的一致性也是个复杂的问题,并且你还不得不更改表结构。最简单的办法还是加个缓存,我已经提了个PR了,你可以参考一下: https://github.com/otale/tale/pull/560

      之前在我笔记本上排查这个问题一直不能再现,因为我笔记本性能还行,即使那段有性能问题的代码执行也很快,环境也是影响问题的关键。

      回复