为了账号安全,请及时绑定邮箱和手机立即绑定

平时的一些trouble-shooting-某服务某rpc远程服务的dubbo接口响应时间过高

2017.04.17 23:55 12765浏览
现象

某接口平时响应时间平均在200ms,但是最近飙升到600ms。

监控指标

查看监控指标,cpu、tcp连接、网卡、load一切正常

分析gc日志
2017-01-25T11:02:21.939+0800: 71437.958: [Full GC [PSYoungGen: 53452K->0K(1317888K)] [ParOldGen: 2785135K->264180K(2796544K)] 2838587K->264180K(4114432K) [PSPermGen: 79636K->79636K(524288K)], 0.2832510 secs] [Times: user=0.73 sys=0.00, real=0.29 secs]
2017-01-25T11:06:04.727+0800: 71660.746: [Full GC [PSYoungGen: 49073K->0K(1315840K)] [ParOldGen: 2776419K->262440K(2796544K)] 2825492K->262440K(4112384K) [PSPermGen: 79636K->79636K(524288K)], 0.2960190 secs] [Times: user=0.82 sys=0.00, real=0.29 secs]
2017-01-25T11:09:28.385+0800: 71864.404: [Full GC [PSYoungGen: 70709K->0K(1249280K)] [ParOldGen: 2746009K->276325K(2796544K)] 2816719K->276325K(4045824K) [PSPermGen: 79636K->79636K(524288K)], 0.3055130 secs] [Times: user=0.83 sys=0.00, real=0.31 secs]
2017-01-25T11:13:33.216+0800: 72109.235: [Full GC [PSYoungGen: 34214K->0K(1324544K)] [ParOldGen: 2780255K->233175K(2796544K)] 2814470K->233175K(4121088K) [PSPermGen: 79655K->79655K(524288K)], 0.2411000 secs] [Times: user=0.60 sys=0.00, real=0.24 secs]
2017-01-25T11:17:44.210+0800: 72360.229: [Full GC [PSYoungGen: 62186K->0K(1286144K)] [ParOldGen: 2789886K->265640K(2796544K)] 2852072K->265640K(4082688K) [PSPermGen: 79660K->79660K(524288K)], 0.2892200 secs] [Times: user=0.74 sys=0.00, real=0.29 secs]
2017-01-25T11:21:59.963+0800: 72615.982: [Full GC [PSYoungGen: 36964K->0K(1310720K)] [ParOldGen: 2783609K->245655K(2796544K)] 2820573K->245655K(4107264K) [PSPermGen: 79660K->79660K(524288K)], 0.2480330 secs] [Times: user=0.64 sys=0.00, real=0.25 secs]
2017-01-25T11:25:45.380+0800: 72841.398: [Full GC [PSYoungGen: 73723K->0K(1262592K)] [ParOldGen: 2755454K->284318K(2796544K)] 2829177K->284318K(4059136K) [PSPermGen: 79660K->79660K(524288K)], 0.3346010 secs] [Times: user=0.85 sys=0.00, real=0.34 secs]
2017-01-25T11:29:39.537+0800: 73075.556: [Full GC [PSYoungGen: 25344K->0K(1315840K)] [ParOldGen: 2774960K->240992K(2796544K)] 2800304K->240992K(4112384K) [PSPermGen: 79660K->79660K(524288K)], 0.2763920 secs] [Times: user=0.70 sys=0.00, real=0.28 secs]
2017-01-25T11:33:36.363+0800: 73312.381: [Full GC [PSYoungGen: 57780K->0K(1309184K)] [ParOldGen: 2779442K->264429K(2796544K)] 2837223K->264429K(4105728K) [PSPermGen: 79660K->79660K(524288K)], 0.2834540 secs] [Times: user=0.76 sys=0.00, real=0.29 secs]
2017-01-25T11:37:42.528+0800: 73558.547: [Full GC [PSYoungGen: 38837K->0K(1294336K)] [ParOldGen: 2784118K->262562K(2796544K)] 2822955K->262562K(4090880K) [PSPermGen: 79660K->79660K(524288K)], 0.2769620 secs] [Times: user=0.71 sys=0.00, real=0.28 secs]
2017-01-25T11:41:38.613+0800: 73794.632: [Full GC [PSYoungGen: 60301K->0K(1312256K)] [ParOldGen: 2784889K->280961K(2796544K)] 2845190K->280961K(4108800K) [PSPermGen: 79660K->79660K(524288K)], 0.3233140 secs] [Times: user=0.88 sys=0.00, real=0.32 secs]
2017-01-25T11:45:24.406+0800: 74020.425: [Full GC [PSYoungGen: 24950K->0K(1301504K)] [ParOldGen: 2769860K->254403K(2796544K)] 2794811K->254403K(4098048K) [PSPermGen: 79669K->79669K(524288K)], 0.2702330 secs] [Times: user=0.69 sys=0.00, real=0.27 secs]
2017-01-25T11:49:17.728+0800: 74253.746: [Full GC [PSYoungGen: 77793K->0K(1246720K)] [ParOldGen: 2787986K->325470K(2796544K)] 2865780K->325470K(4043264K) [PSPermGen: 79690K->79690K(524288K)], 0.3316160 secs] [Times: user=0.91 sys=0.00, real=0.34 secs]
2017-01-25T11:53:02.996+0800: 74479.015: [Full GC [PSYoungGen: 40194K->0K(1296896K)] [ParOldGen: 2774411K->263508K(2796544K)] 2814606K->263508K(4093440K) [PSPermGen: 79690K->79690K(524288K)], 0.2693080 secs] [Times: user=0.70 sys=0.00, real=0.27 secs]
2017-01-25T11:56:29.604+0800: 74685.623: [Full GC [PSYoungGen: 91113K->0K(1305088K)] [ParOldGen: 2684520K->609246K(2796544K)] 2775634K->609246K(4101632K) [PSPermGen: 79690K->79690K(524288K)], 0.9831970 secs] [Times: user=3.17 sys=0.00, real=0.98 secs]
2017-01-25T11:59:01.868+0800: 74837.887: [Full GC [PSYoungGen: 104932K->0K(1287680K)] [ParOldGen: 2779540K->433632K(2796544K)] 2884472K->433632K(4084224K) [PSPermGen: 79690K->79690K(524288K)], 0.7554340 secs] [Times: user=2.14 sys=0.00, real=0.76 secs]
2017-01-25T12:01:48.453+0800: 75004.472: [Full GC [PSYoungGen: 36636K->0K(1247744K)] [ParOldGen: 2735083K->266286K(2796544K)] 2771719K->266286K(4044288K) [PSPermGen: 79690K->79690K(524288K)], 0.3109250 secs] [Times: user=0.87 sys=0.00, real=0.32 secs]
2017-01-25T12:04:36.500+0800: 75172.519: [Full GC [PSYoungGen: 31085K->0K(1299456K)] [ParOldGen: 2786949K->232197K(2796544K)] 2818034K->232197K(4096000K) [PSPermGen: 79690K->79690K(524288K)], 0.2387330 secs] [Times: user=0.58 sys=0.00, real=0.24 secs]

整理了25号其中一台机器的gc日志,过滤了FullGC的日志,都是STW操作,不够从日志可以看出,年轻代完全会被回收,老年代也会回收90%,基本上每次都会回收90%。持久代没变化,但是持久代我们在参数配的512M空间是足够的。目前才80M的持久代已经足够使用。另外老年代回收之后的HEAP空间也回收明显~~90%左右,heap的总容量也是足够的啦。那那那看来JVM也不用优化....那是为啥咧。。继续分析...

内存分析

图片描述

从分布图可以看出,内存中剩余空间还是很大的。并且没有特别流弊特别大的对象存活,百分比最高的也只是tomcat的webclassloader,无非请求数太多造成单例比较多,这不会影响接口速度。

配置ngxin,使负载均衡不会打到线上机,内网进行压测重现

图片描述

从以上报告可以看出,压测一切正常。响应最高的也就260ms

查看redis监控

发现不是redis造成的,io都正常

分析dubbo日志

因为本服务需要给外部提供远程RPC服务。
通过awk统计dubbo日志发现在请求某些数据的时候返回值过大,基本上达到了8M到12M,导致了dubbo在传输大对象时造成了时间过长,从而影响了dubbo的接口响应时间飙升至600ms。

解决

和调用方沟通,把对方需要的字段留下,其他字段去掉,进行瘦身。发布之后,一切正常。

点击查看更多内容

本文原创发布于慕课网 ,转载请注明出处,谢谢合作

16人点赞

若觉得本文不错,就分享一下吧!

评论

相关文章推荐

正在加载中
意见反馈 邀请有奖 帮助中心 APP下载
官方微信

举报

0/150
提交
取消