Poison

发表于

GC 日志：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
2022-01-17T13:39:14.399+0800: 920001.780: [GC pause (G1 Evacuation Pause) (young), 0.0109317 secs]
   [Parallel Time: 9.7 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 920001780.8, Avg: 920001781.0, Max: 920001781.3, Diff: 0.5]
      [Ext Root Scanning (ms): Min: 7.4, Avg: 7.9, Max: 8.4, Diff: 1.0, Sum: 15.8]
      [Update RS (ms): Min: 0.8, Avg: 0.9, Max: 1.0, Diff: 0.2, Sum: 1.8]
         [Processed Buffers: Min: 4, Avg: 4.5, Max: 5, Diff: 1, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.2, Avg: 0.4, Max: 0.7, Diff: 0.5, Sum: 0.8]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 9.1, Avg: 9.4, Max: 9.6, Diff: 0.5, Sum: 18.7]
      [GC Worker End (ms): Min: 920001790.4, Avg: 920001790.4, Max: 920001790.4, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.1 ms]
   [Eden: 0.0B(102.0M)->0.0B(102.0M) Survivors: 0.0B->0.0B Heap: 2037.9M(2048.0M)->2037.9M(2048.0M)]
 [Times: user=0.02 sys=0.00, real=0.01 secs]
2022-01-17T13:39:14.416+0800: 920001.797: [Full GC (Allocation Failure)  2037M->1195M(2048M), 3.2218960 secs]
   [Eden: 0.0B(102.0M)->0.0B(605.0M) Survivors: 0.0B->0.0B Heap: 2037.9M(2048.0M)->1195.7M(2048.0M)], [Metaspace: 204152K->203357K(1247232K)]
 [Times: user=3.98 sys=0.00, real=3.22 secs]
2022-01-17T13:39:17.638+0800: 920005.020: [GC concurrent-mark-abort]
2022-01-17T13:39:18.323+0800: 920005.704: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.1329421 secs]
   [Parallel Time: 128.8 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 920005705.4, Avg: 920005705.4, Max: 920005705.4, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 8.6, Avg: 8.6, Max: 8.6, Diff: 0.0, Sum: 17.2]
      [Update RS (ms): Min: 47.3, Avg: 47.4, Max: 47.4, Diff: 0.1, Sum: 94.8]
         [Processed Buffers: Min: 227, Avg: 239.5, Max: 252, Diff: 25, Sum: 479]
      [Scan RS (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.2]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 71.8, Avg: 71.8, Max: 71.8, Diff: 0.1, Sum: 143.6]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 127.9, Avg: 127.9, Max: 127.9, Diff: 0.0, Sum: 255.8]
      [GC Worker End (ms): Min: 920005833.3, Avg: 920005833.3, Max: 920005833.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 3.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.5 ms]
   [Eden: 263.0M(605.0M)->0.0B(522.0M) Survivors: 0.0B->43.0M Heap: 1458.7M(2048.0M)->1238.3M(2048.0M)]
 [Times: user=0.26 sys=0.00, real=0.14 secs]
阅读全文 »
Poison

发表于

OperatingSystemMXBean 中的 getFreePhysicalMemorySize() 方法返回的值为不含缓存的可用物理内存，该指标不能很好的反应 Linux 中实际可用的物理内存，因为 Linux 尽量使用内存的特性，该指标返回的数据几乎总是接近总物理内存，我们根据 /proc/meminfo 中返回的数据采集出类似 free 命令中 available 列的值以便更好的监测可用物理内存。

阅读全文 »
Poison

发表于

同事反馈有一组应用的定时任务不执行了，简单看了下，该应用未定义过基于 TaskScheduler 或 ScheduledExecutorService 实现的 Bean，此时 Spring 会在 ScheduledTaskRegistrar.scheduleTasks() 中创建一个单线程的任务调度器：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
/**
 * Schedule all registered tasks against the underlying {@linkplain
 * #setTaskScheduler(TaskScheduler) task scheduler}.
 */
protected void scheduleTasks() {
  if (this.taskScheduler == null) {
    this.localExecutor = Executors.newSingleThreadScheduledExecutor();
    this.taskScheduler = new ConcurrentTaskScheduler(this.localExecutor);
  }
  if (this.triggerTasks != null) {
    for (TriggerTask task : this.triggerTasks) {
      addScheduledTask(scheduleTriggerTask(task));
    }
  }
  if (this.cronTasks != null) {
    for (CronTask task : this.cronTasks) {
      addScheduledTask(scheduleCronTask(task));
    }
  }
  if (this.fixedRateTasks != null) {
    for (IntervalTask task : this.fixedRateTasks) {
      addScheduledTask(scheduleFixedRateTask(task));
    }
  }
  if (this.fixedDelayTasks != null) {
    for (IntervalTask task : this.fixedDelayTasks) {
      addScheduledTask(scheduleFixedDelayTask(task));
    }
  }
}
阅读全文 »
Poison

发表于

前段时间有线上实例被负载均衡判定不可用，随即被摘除，同时我们收到该实例的 JVM GC 耗时较长的告警及负载较高的告警。从操作系统级别的监控可以看到磁盘读取速度几乎达到该规格的上限，近 120MB/s，IOPS 为 2200 左右，使用 ssh 登录该实例需要等待很久，且进入实例后几乎无法输入命令，2 核的机器负载达到了 20 左右。持续了七八分钟会恢复正常，恢复正常后我首先查看了 GC 日志，确认是否存在大量 FullGC，但是从日志中并未发现长时间的 Full GC，普通的 GC 的 real 耗时都很久，部分 GC 日志如下：

阅读全文 »
Poison

发表于

业务方反馈一到晚上就有接口时好时坏，用浏览器访问的话表现就是一直处于 pending 状态，直到超时，多次尝试的话有时又会恢复正常。开始怀疑是接口内部实现问题，于是我在多个请求处于 pending 状态时拉取了栈帧进行检查，发现没有符合该接口实现的栈帧。于是怀疑连接建立问题，使用 telnet 443 对负载均衡服务器发起连接，表现也是卡住，于是去查了该负载均衡实例的监控，果然是活跃连接数已经达到该实例的上限导致，因为当时选用的最低配，根本不能支撑现有的业务量，于是直接升配解决。可以猜测该实例到达连接数上限时采取的策略是丢弃 SYN 包，导致客户端重传直到超时，而没有采取直接返回 RST 的方式。当然这只是我根据现象进行的推测，具体的原因可以用 Wireshark 抓包确认，只不过这次还没用到就解决了该问题。

之前遇到类似的问题，最后排查出来是因为风控系统将特定 IP 加入了负载均衡层的黑名单，表现也是一直处于 pending 状态，猜测负载均衡服务器的实现也是丢弃 SYN 包。

Reference

怎么理解SLB的并发连接数和PTS里的并发？ - 性能测试 PTS - 阿里云