Skywalking对应的ES的CPU很高的问题

结论

原因1:ES的新生代配置的太小,yong gc频率很高, 1s一次yonggc
解决方案:手动设置新生代、老年代比例 -XX:NewRatio=1

原因2:ES的索引没有配置为高性能写模式( 这个配置立杆见影 )
解决方案:对skywalking对应的index添加如下配置

 "index.merge.scheduler.max_thread_count" : "1",
 "index.refresh_interval" : "30s",
 "index.translog.durability" : "async",
 "index.translog.sync_interval" : "120s"

原因3: skywalking的agent上传JVM状态信息过于频繁,导致产生大量的ES request(这个不是主要原因)
解决方案: 修改agent代码,设置JVM上传频率为30s一次

环境

ES实例:4核 * 14G, 只有一台实例,基于docker起的
OAPServer:只有一台,512M
agent节点:也就是JVM实例大概50个

解决过程

agent 上传JVM信息太频繁

遇到的现象是,已经把oap-server的sample比例设置为1%了,可以看到skywalking中追踪的数据很少,但是发现ES所占CPU依然很高


image.png

修改oapServer把写入ES的BulkRequest的log级别修改为debug模式,发现短时间内的确有大量的Request


image.png

通过分析oapServer的堆栈发现:几乎所有的Request都是Metric相关的(service_relation_server_p90、instance_jvm_memory等等),而这里面的绝大部分又都是jvm相关的
jvisualvm

查看源码发现,jvm信息是通过单独的grpc接口上传到oapServer的,并且是1S收集一次, 1S上传一次,如此高频率的收集jvm数据,每一次收集的有多个指标(memory cpu gc),每个指标又根据分钟、小时、天、月更新多个index,就会导致产生大量的UpdateRequest对象,假设有50台JVM实例,每上传一次JVM数据产生18个Request,就会导致 50 * 18 = 900 个Request,也就是说,在没有处理任何TraceSegment的情况下,每秒就要产生900个Request


image.png

我这次是直接把1s修改成了30s,重新打包agent,部署、重启,查看日志发现发送到ES的Request相对来说是少了一些,但是ES的cpu占用并没有下降很多大概从300%下降至250%左右

ES的新生代配置的太小

由于我们是直接用docker起的ES,用的官方的镜像,官方镜像用的JDK12,在这个docker容器中jmap jstat并不能用,好在ES直接把gclog打印到了文件中,查看gclog才发现yonggc是如此的频繁,甚至不到1s一次

[2019-07-30T11:03:20.242+0000][1][gc,start     ] GC(158) Pause Young (Allocation Failure)
[2019-07-30T11:03:20.242+0000][1][gc,task      ] GC(158) Using 4 workers of 4 for evacuation
[2019-07-30T11:03:20.258+0000][1][gc,age       ] GC(158) Desired survivor size 17432576 bytes, new threshold 6 (max threshold 6)
[2019-07-30T11:03:20.258+0000][1][gc,age       ] GC(158) Age table with threshold 6 (max threshold 6)
[2019-07-30T11:03:20.258+0000][1][gc,age       ] GC(158) - age   1:     954344 bytes,     954344 total
[2019-07-30T11:03:20.258+0000][1][gc,age       ] GC(158) - age   2:       4864 bytes,     959208 total
[2019-07-30T11:03:20.258+0000][1][gc,age       ] GC(158) - age   3:       2256 bytes,     961464 total
[2019-07-30T11:03:20.258+0000][1][gc,age       ] GC(158) - age   4:     391800 bytes,    1353264 total
[2019-07-30T11:03:20.258+0000][1][gc,age       ] GC(158) - age   5:     119784 bytes,    1473048 total
[2019-07-30T11:03:20.258+0000][1][gc,age       ] GC(158) - age   6:       1456 bytes,    1474504 total
[2019-07-30T11:03:20.258+0000][1][gc,heap      ] GC(158) ParNew: 275195K->2126K(306688K)
[2019-07-30T11:03:20.258+0000][1][gc,heap      ] GC(158) CMS: 798450K->798452K(3853568K)
[2019-07-30T11:03:20.258+0000][1][gc,metaspace ] GC(158) Metaspace: 85950K->85950K(1128448K)
[2019-07-30T11:03:20.258+0000][1][gc           ] GC(158) Pause Young (Allocation Failure) 1048M->781M(4062M) 15.861ms
[2019-07-30T11:03:20.258+0000][1][gc,cpu       ] GC(158) User=0.06s Sys=0.00s Real=0.02s
[2019-07-30T11:03:20.258+0000][1][safepoint    ] Leaving safepoint region
[2019-07-30T11:03:20.258+0000][1][safepoint    ] Total time for which application threads were stopped: 0.0163155 seconds, Stopping threads took: 0.0001191 seconds
[2019-07-30T11:03:20.642+0000][1][safepoint    ] Application time: 0.3842620 seconds
[2019-07-30T11:03:20.642+0000][1][safepoint    ] Entering safepoint region: GenCollectForAllocation
[2019-07-30T11:03:20.643+0000][1][gc,start     ] GC(159) Pause Young (Allocation Failure)
[2019-07-30T11:03:20.643+0000][1][gc,task      ] GC(159) Using 4 workers of 4 for evacuation
[2019-07-30T11:03:20.659+0000][1][gc,age       ] GC(159) Desired survivor size 17432576 bytes, new threshold 6 (max threshold 6)
[2019-07-30T11:03:20.659+0000][1][gc,age       ] GC(159) Age table with threshold 6 (max threshold 6)
[2019-07-30T11:03:20.659+0000][1][gc,age       ] GC(159) - age   1:    1309016 bytes,    1309016 total
[2019-07-30T11:03:20.659+0000][1][gc,age       ] GC(159) - age   2:      38944 bytes,    1347960 total
[2019-07-30T11:03:20.659+0000][1][gc,age       ] GC(159) - age   3:       2616 bytes,    1350576 total
[2019-07-30T11:03:20.659+0000][1][gc,age       ] GC(159) - age   4:        720 bytes,    1351296 total
[2019-07-30T11:03:20.659+0000][1][gc,age       ] GC(159) - age   5:     378152 bytes,    1729448 total
[2019-07-30T11:03:20.659+0000][1][gc,age       ] GC(159) - age   6:     111352 bytes,    1840800 total
[2019-07-30T11:03:20.659+0000][1][gc,heap      ] GC(159) ParNew: 274766K->2257K(306688K)
[2019-07-30T11:03:20.659+0000][1][gc,heap      ] GC(159) CMS: 798452K->798453K(3853568K)
[2019-07-30T11:03:20.659+0000][1][gc,metaspace ] GC(159) Metaspace: 85950K->85950K(1128448K)

关键是无论怎么增大Xms XmX和deploy.resources.limits.memory都不管用,新生代的大小都是只有275195K这么大,下面是我们的ES启动配置

image.png

后来网上搜了之后才发现,原来CMS 默认的新生代并不是总堆大小的1/3,必须显式设置XX:NewRatio才可以。可以参考https://www.jianshu.com/p/832fc4d4cb53
于是手动设置XX:NewRatio=1,设置了之后发现yonggc频率变成大概6s一次,CPU占用也大概下降至180%左右,其实6s一次还是挺频繁,后续还是需要考虑增加ES的node,以及增加内存来分散压力

ES的高性能写模式

其实这块儿主要参考了https://blog.csdn.net/lengxiangwu/article/details/90445014,大家可以直接看这篇博文
或者参考官网:https://www.elastic.co/guide/en/elasticsearch/reference/6.8/tune-for-indexing-speed.html
核心就是修改index的设置, 个人实现发现主要起作用的是index.refresh_interval这个参数

 "index.merge.scheduler.max_thread_count" : "1",
 "index.refresh_interval" : "30s",
 "index.translog.durability" : "async",
 "index.translog.sync_interval" : "120s"

由于skywalking是通过template的方式创建index,一个一个修改template的配置比较麻烦,我就直接修改了skywalking的代码,添加了上面的配置,然后批量删除旧的与日期相关的index(之所以没有全部删除是因为全部删除的话需要重启agent), 重新打包、部署skywalking-server

org.apache.skywalking.oap.server.storage.plugin.elasticsearch.base.StorageEsInstaller

private JsonObject createSetting() {
        JsonObject setting = new JsonObject();
        setting.addProperty("index.number_of_shards", indexShardsNumber);
        setting.addProperty("index.number_of_replicas", indexReplicasNumber);
        setting.addProperty("analysis.analyzer.oap_analyzer.type", "stop");

        //custom config for better es update performance
        setting.addProperty("index.refresh_interval", "30s");
        setting.addProperty("index.translog.durability", "async");
        setting.addProperty("index.translog.sync_interval", "120s");
        setting.addProperty("index.merge.scheduler.max_thread_count", "1");
        return setting;
    }

重启skywalking-server,查看es的index配置,发现配置已经生效


image.png

再次观察ES的CPU占用情况,已经降到了100%左右,至此 ES的CPU优化暂告一段落吧, 由于skywalking对ES的操作实在是太多了,想完全把ES的CPU降下来是不太现实的,只能考虑增加ES机器,减小采样频率了

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 220,492评论 6 513
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 94,048评论 3 396
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 166,927评论 0 358
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 59,293评论 1 295
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 68,309评论 6 397
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 52,024评论 1 308
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,638评论 3 420
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 39,546评论 0 276
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 46,073评论 1 319
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 38,188评论 3 340
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 40,321评论 1 352
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,998评论 5 347
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,678评论 3 331
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 32,186评论 0 23
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 33,303评论 1 272
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 48,663评论 3 375
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 45,330评论 2 358

推荐阅读更多精彩内容