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

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

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

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，无非请求数太多造成单例比较多，这不会影响接口速度。

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

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

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

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