背景

自己在阿里云上搭建了一个个人 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 上，但 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 方法上

本文由 zealzhangz 创作，采用知识共享署名4.0 国际许可协议进行许可
本站文章除注明转载/出处外，均为本站原创或翻译，转载前请务必署名
最后编辑时间为: 2019/12/28 13:12

暴走的程序猿

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

2019-10-08 回复
1. 海阔天空
  
  @暴走的程序猿
  数据库保存的是MD，如果直接转成HTML保存，你再次编辑的时候就变成编辑HTML了，恐怕你要懵逼了。除非同时保存MD和HTML，这样维护MD和HTML的一致性也是个复杂的问题，并且你还不得不更改表结构。最简单的办法还是加个缓存，我已经提了个PR了，你可以参考一下： https://github.com/otale/tale/pull/560
  
  之前在我笔记本上排查这个问题一直不能再现，因为我笔记本性能还行，即使那段有性能问题的代码执行也很快，环境也是影响问题的关键。
  
  2019-10-09 回复

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

背景