说下那些导致Presto查询变慢的JVM Bug和解决方法

背景

维护Presto集群,遇到了一些JVM Bug会严重导致Presto查询变慢,这里分享下Bugs表现及解决方法。

Ref Proc 耗时太久

线上Presto运行一段时间后,查询会越来越慢,打了下火焰图,发现30%的CPU都浪费在young gc上了,看了下gc log,如下:

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

2020-12-21T20:50:15.009+0800: 4753827.928: [GC pause (GCLocker Initiated GC) (young) (initial-mark), 0.5723063 secs]
[Parallel Time: 66.9 ms, GC Workers: 33]
[GC Worker Start (ms): Min: 4753827940.4, Avg: 4753827940.5, Max: 4753827940.7, Diff: 0.4]
[Ext Root Scanning (ms): Min: 26.2, Avg: 27.3, Max: 54.9, Diff: 28.7, Sum: 899.6]
[Update RS (ms): Min: 0.0, Avg: 9.2, Max: 9.8, Diff: 9.8, Sum: 304.3]
[Processed Buffers: Min: 0, Avg: 19.9, Max: 35, Diff: 35, Sum: 657]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 0.5, Avg: 11.2, Max: 13.8, Diff: 13.3, Sum: 369.9]
[Termination (ms): Min: 0.0, Avg: 7.8, Max: 8.4, Diff: 8.4, Sum: 256.8]
[Termination Attempts: Min: 1, Avg: 1.5, Max: 4, Diff: 3, Sum: 51]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.5]
[GC Worker Total (ms): Min: 55.3, Avg: 55.5, Max: 55.7, Diff: 0.5, Sum: 1831.3]
[GC Worker End (ms): Min: 4753827996.0, Avg: 4753827996.0, Max: 4753827996.1, Diff: 0.1]
[Code Root Fixup: 0.4 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.6 ms]
[Other: 504.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 501.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.5 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 320.0M(3264.0M)->0.0B(3392.0M) Survivors: 416.0M->288.0M Heap: 9068.7M(72.0G)->8759.2M(72.0G)]
[Times: user=1.70 sys=0.39, real=0.57 secs]

从上面我们可以看到 Ref Proc: 501.3 ms,总共young gc耗时0.57s,而Ref Proc耗时就达到了0.5s。我们需要看下Ref Proc耗时主要在哪个地方。
我们通过配置gc参数-XX:+PrintReferenceGC,可以看到详细的Reference GC时间,并且如下图Case,JNI Weak Reference是主要瓶颈点。

Read More

解决JIT Deoptimization,ES插入性能提升7倍

背景描述

ES节点写入到5.7K,会产生比较多的reject,CPU利用率才30%,部分索引延迟在增加。如图所示:

CPU使用率在30%,但是Rejected记录达到8W行

原因分析

写入场景,CPU打不满且出现异常,根据之前Presto的经验,大概率是JVM问题。打下火焰图看下:

可以看到接近35%的CPU在做JIT Deoptimization。

JIT

为了提高热点代码(Hot Spot Code)的执行效率,在运行时,虚拟机将会把这些代码编译成与本地平台相关的机器码,并进行各种层次的优化,完成这个任务的编译器称为即时编译器(JIT)。

Read More

Presto Master JVM Core问题调研

背景

Presto master出现jvm coredump情况,排查问题,这里记录下排查过程。

排查过程

先看下JVM Coredump日志:

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
#
# There is insufficient memory for the Java Runtime Environment to continue.
# Native memory allocation (mmap) failed to map 12288 bytes for committing reserved memory.
# Possible reasons:
# The system is out of physical RAM or swap space
# In 32 bit mode, the process size limit was hit
# Possible solutions:
# Reduce memory load on the system
# Increase physical memory or swap space
# Check if swap backing store is full
# Use 64 bit Java on a 64 bit OS
# Decrease Java heap size (-Xmx/-Xms)
# Decrease number of Java threads
# Decrease Java thread stack sizes (-Xss)
# Set larger code cache with -XX:ReservedCodeCacheSize=
# This output file may be truncated or incomplete.
#
# Out of Memory Error (os_linux.cpp:2640), pid=22120, tid=0x00007ef9d2ed3700
#
# JRE version: Java(TM) SE Runtime Environment (8.0_144-b01) (build 1.8.0_144-b01)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.144-b01 mixed mode linux-amd64 )
# Core dump written. Default location: /data1/cluster-data/core or core.22120 (max size 52428800 kB). To ensure a full core dump, try "ulimit -c unlimited" before starting Java again
#


--------------- T H R E A D ---------------

Current thread (0x00007eff5eaf5000): JavaThread "IPC Client (1499102350) connection to presto-host.nmg01/data-node:8020 from user" daemon [_thread_new, id=28463, stack(0x00007ef9d2e93000,0x00007ef9d2ed4000)]

Stack: [0x00007ef9d2e93000,0x00007ef9d2ed4000], sp=0x00007ef9d2ed2760, free space=253k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0xacb18a] VMError::report_and_die()+0x2ba
V [libjvm.so+0x4ff4db] report_vm_out_of_memory(char const*, int, unsigned long, VMErrorType, char const*)+0x8b
V [libjvm.so+0x927d23] os::Linux::commit_memory_impl(char*, unsigned long, bool)+0x103
V [libjvm.so+0x927dec] os::pd_commit_memory(char*, unsigned long, bool)+0xc
V [libjvm.so+0x9217ba] os::commit_memory(char*, unsigned long, bool)+0x2a
V [libjvm.so+0x9261df] os::pd_create_stack_guard_pages(char*, unsigned long)+0x7f
V [libjvm.so+0xa6ffce] JavaThread::create_stack_guard_pages()+0x5e
V [libjvm.so+0xa797b4] JavaThread::run()+0x34
V [libjvm.so+0x92a338] java_start(Thread*)+0x108
C [libpthread.so.0+0x7dc5] start_thread+0xc5

Read More

Presto 在滴滴的探索和实践

Presto 简介

简介

Presto是Facebook 开源的 MPP (Massive Parallel Processing) SQL 引擎,其理念来源于一个叫 Volcano 的并行数据库,该数据库提出了一个并行执行 SQL 的模型,它被设计为用来专门进行高速、实时的数据分析。Presto是一个SQL计算引擎,分离计算层和存储层,其不存储数据,通过Connector SPI实现对各种数据源(Storage)的访问。

架构

Presto沿用了通用的Master-Slave架构,一个Coordinator,多个Worker。Coordinator负责解析SQL语句,生成执行计划,分发执行任务给Worker节点执行;Worker节点负责实际执行查询任务。Presto提供了一套Connector接口,用于读取元信息和原始数据,Presto 内置有多种数据源,如 Hive、MySQL、Kudu、Kafka 等。同时,Presto 的扩展机制允许自定义 Connector,从而实现对定制数据源的查询。假如配置了Hive Connector,需要配置一个Hive MetaStore服务为Presto提供Hive元信息,Worker节点通过Hive Connector与HDFS交互,读取原始数据。

实现低延时原理

Presto是一个交互式查询引擎,我们最关心的是Presto实现低延时查询的原理,以下几点是其性能脱颖而出的主要原因。

  • 完全基于内存的并行计算
  • 流水线
  • 本地化计算
  • 动态编译执行计划
  • 小心使用内存和数据结构
  • GC控制
  • 无容错

Presto 在滴滴的应用

业务场景

  • Hive SQL查询加速
  • 数据平台Ad-Hoc查询
  • 报表(BI报表、自定义报表)
  • 活动营销
  • 数据质量检测
  • 资产管理
  • 固定数据产品

Read More

Jetty导致Presto堆外内存泄露的排查过程

背景

一个Presto集群报警,显示Coordinator内存不足。看了下,发现RES内存(86.7G) > XMX(72G) + 堆外内存(10G),然后看了下Presto UI里Resource Utilization的Non-Heap Memory Used,只用了200M。问题奇怪,pmap查看进程的内存映像信息,如下:

1
2
3
4
5
6
7
8
9
10
11
12
[presto@hostname ~/presto-current]$ pmap -x 107870 | sort -rn -k3 | head -n 10
total kB 106752092 86763996 86684760
00007fd673000000 75644928 61078708 61078708 rw--- [ anon ]
00007fd5c8000000 2654208 2537116 2537116 rw--- [ anon ]
000000000120a000 1244772 1244644 1244644 rw--- [ anon ]
00007fd5803cf000 520388 497972 497972 rw--- [ anon ]
00007fd08c836000 149720 149720 149720 rw--- [ anon ]
00007fd0e2fe2000 147620 147620 147620 rw--- [ anon ]
00007fd0d9b35000 146920 146920 146920 rw--- [ anon ]
00007fe964000000 116672 114164 114164 rwx-- [ anon ]
00007fd0612b1000 111932 111932 111932 rw--- [ anon ]

第一列表示虚拟空间地址,第二列表示该项在虚拟空间中占用的大小,第三列表示RSS,第四列表示DIRTY,第五列表示该项名称(anon是佚名的)。

jmap -heap 发现堆内内存占用正常,然后我jmap dump了一份内存,dump后发现只有700M+,应该与堆内存无关了,既然这样查找直接从堆外内存入手了。

Read More

记一次Presto Worker OOM的查找过程

背景

最近Presto集群又上线了几个新业务,伴之而来的是OOM很频繁,且发生时间多在早晨8点左右,线上稳定性是高优需要解决的,所以查找了下导致Presto集群OOM的原因,发现了一些问题,这里抛砖引玉下,可能其他使用Presto的用户也会遇到类似的问题。

排查过程

我给一些业务划分了不同的label,这里说明下我们把Presto引擎改进了下,可以动态将机器划分不同的label,这样SQL查询时候指定不同的label,SQL调度时只根据指定的label查找机器即可。之后发现一个业务方的SQL会导致集群OOM。具体表现为,多次Full GC,之后OOM,看GC日志第一感觉应该是有内存泄露。

我通过审计日志(之前通过event-listener实现了个日志审计模块)拿到OOM时2K左右条SQL,发现SQL都是简单的SQL,类似这种:

1
2
SELECT * FROM table WHERE year='2020' AND month='06' AND day='01' LIMIT 10;

根据SQL,我猜测可能以下2种原因导致了OOM:

  • 查询的表存在Hive视图(我让Presto支持了Hive视图)
  • 异常SQL触发了内存泄露

Read More

PrestoDB和PrestoSQL比较及选择

Presto 社区分家后搞了2个项目,分别为 PrestoDB 和 PrestoSQL,同时他们都成立了自己的基金会。而去年国庆时候,abei写了篇文章比对了2个分支的进展,链接见:PrestoDB VS PrestoSQL发展比较。 而现在已经分家17个月了,那我们简单梳理下这2个分支的主要核心功能:

PrestoDB

  • Connector:ElasticSearch 及 Druid
  • Master 和Worker 通信协议支持二进制
  • Orc 及 Parquet读写性能优化
  • Hive写数据支持指定压缩格式
  • task通信协议可以指定 thrift
  • spi pushdown
  • MapReduce-style shuffle,支持部分 etl 任务及大查询
  • fix bug 及 improve performace

PrestoSQL

  • Connector:ElasticSearch和MemSQL
  • spi pushdown
  • S3优化读取
  • join 延时物化
  • 大量的 fix bug 及 improve performance

Read More