更新arthas}请教懂Java后端关于初学的交易功能的压测

JennyFaceOff

在校生通信相关专业，最近自学Java，在做一个烂大街的“亿级流量秒杀”项目。先别吐槽选Java后端以及项目本身的事，我遇到了一个问题想请教。字数挺多但对专业的应该轻车熟路了。
问题背景（熟悉可以快速略过）---------------------------------------
这个项目是一个springboot电商秒杀项目，有下单功能，下面是部分目录，项目主体是另一个基础版秒杀，希望可以对问题有所参考：

然后我做到了第7章交易性能优化。这个交易是前端发送一个ajax的POST请求到".../order/createorder?token=..."域名下，后端OrderController从请求中获取itemId、amount和promoId（促销活动id），然后在其createOrder方法中先获取token中的用户信息来确定用户是否登录，如果是则调用OrderService的createOrder方法（参数是user的id，itemId，promoId和amount）。

OrderService的createOrder方法上来先用itemService根据itemId获取商品模型（要读二次MySQL数据库，其中要读一次promo信息），然后用userService根据userId获取用户模型（再读一次数据库），接着根据promoId的有无来确定促销活动是否合法。这些通过后再用itemService的decreaseStock来减库存（要update一次数据库）。之后再组装好一个OrderModel，将它插入进入MySQL的order_info表中（要insert一次数据库），然后要再调用itemService的increaseSales方法来更改商品销量（要update一次数据库），最后返回前端。

上面涉及6次数据库io操作，课程视频里用jmeter对那个POST请求做了压测，200个线程ramp-up5秒循环20次，最后吞吐量每秒200多，平均响应时间500ms左右；改成1000个线程，吞吐量可以达到400多，但是平均响应时间得2秒了。
为此，课程首先做的优化就是，对OrderService获取商品模型和用户模型这两个步骤采用redis缓存：第一次时才读数据库，并把信息存入redis，而之后一定时间内读redis内存中存的信息。
课程在优化后又做了压测，结果1000线程的压测可以做到吞吐量1200左右，平均响应也到了500ms左右，提升挺明显的。
-------------------------------------------------------


然后我实践这一部分遇到了问题。我在优化前压测200个线程也是200多tps，平均响应500ms左右；结果优化后还是200多tps，响应时间也没啥变化。如果改成1000个线程，tps没啥变化，但是平均响应时间会降到2、3秒。这不是完全没起到优化作用吗？

课程用的是4个阿里云服务器，而我当时是电脑用vmware开了4个CentOS虚拟机（一nginx，一MySQL+redis，两server程序）做这个项目，为了判断是不是环境的问题我改到了Windows本地部署，结果还是一个吊样。我考虑会不会是MySQL某个语句执行太慢了拖累了整体，打开慢查询日志改long_query_time为0.01秒，结果发现也只有减库存的语句用时多一点，但也只有10、20来ms，和平均响应的几百ms比根本不算事。

我在课程问答区没看到有人和我类似情况，网上搜了一圈也没人问这个问题，所有人优化后都能有提升。本来我想过”反正没报错干脆继续往下做吧“，但是担心影响后续完成情况，不明不白吊着很难受。这个问题卡了我几天了，我完全没辙了，于是想到来娘家发帖问问，泥潭好心人如果能告诉我可行的排查方法我可以量力有偿感谢。
————————————————————————
更新：
16楼更新了手动打印controller和service中各部分用时，显示了我springboot内用时不算高。
30楼更新了使用arthas查看orderController类中的createorder方法的trace，显示用时也不高。搜了下可以追踪DispatchServlet，但是我希望能看到jmeter（jar形式）是如何压测的完整堆栈，请问该如何实现？

marxel

我觉得问题出在redis身上

JennyFaceOff

marxel 发表于 2022-11-24 20:44
我觉得问题出在redis身上

这种情况确实唯一变量就是redis了。刚刚我又拿了别人的源码压缩包解压，用别人的代码跑了一遍，还是类似的结果，现在看来不是我代码的问题了；本地没用nginx，说明不是网络的问题。
目前来看可能区别就是那几个地方：
1.MySQL，我本机8.0版本，CentOS是5.7版本，但是效果差不多，应该也不是MySQL问题；
2.redis，可是不知道如何看瓶颈在哪，内存没占满。另外我jedis池的max-active和min-idle设置的和视频里一样（50，20）；
3.磁盘，我虚拟机装在致钛1tb的盘上，本地项目放电脑自带盘上，似乎也不是磁盘原因...
4.jmeter，我在官网下的jmeter，版本肯定比视频里的新很多。我压测商品详情页的时候每次优化提升都很明显，tps最后都可以到快6000（虚拟机部署），然后压测交易时是那压测商品详情页的jmx文件改的。难道是这里疏忽搞错了？我真百思不得其解，都想不管这个问题继续往下做了

中川夏纪

你数据初始化到 redis 里了吗

tsubasa9

有可能是虚拟机的问题

JennyFaceOff

中川夏纪 发表于 2022-11-24 21:06
你数据初始化到 redis 里了吗

把商品缓存的这部分代码是这样的：

用户那个也类似。最开始跑之前debug过，手动下单里确实是第一次if里是true，之后是false，所以缓存应该生效了。
jmeter设置是这样的：

难不成是我jmeter用法不对？我是先打开后端程序，然后浏览器打开页面登录，进入商品详情页，f12打开工具，点下单，找到那次请求，复制了带token的域名，粘贴到jmeter的路径上，先用1线程循环1次试一试，如果成功再开启多个线程多个循环的压测。（库存从设置的20多w试到现在10多w了）

ryanz

先把每一步的时间整出来看一看呗，比如读写数据库的时间，读写redis的时间。特别是读写redis的时间，有次我的组员在那瞎整版本，sdk和redis集群的版本不匹配，读一次 redis 200ms，不过我那是go，java按理很少这样。

JennyFaceOff

tsubasa9 发表于 2022-11-24 21:17
有可能是虚拟机的问题

可本地试过，程序更改前后变化不大。
（虚拟机出现过问题，不过是压测如果线程多了会有SocketException: Connection reset的报错，20000个会出5、6000个这种错，我暂时没管）

董卓

抓个javacore，拉个flamegraph看看有什么预料之外的热点
上arthas看看也行

d2loader

火焰图，请

char1st

Redis有慢日志的

赤色彗星SEXY

redis是单线程的。要散列到多个redis
由于redis单线程 所以如果订单数据压缩了再塞进去

zxc111

上埋点，Prometheus+grafana请，要不手动打日志看耗时也行。
顺带看下资源是不是满了，比如cpu

----发送自 OnePlus KB2005,Android 12

super_uni

localhost？本地压本地？你得看看cpu是不是爆了

— from OPPO PEGM00, Android 12 of S1 Next Goose v2.5.4

紧那罗

本地压本地确实不是理想的测试环境

另外我觉得没学瓶颈分析空学调优是根本问题
几位坛友说的方法你先试试呗 查log看耗时 或者arthas看看火焰图

JennyFaceOff

zxc111 发表于 2022-11-25 00:21
上埋点，Prometheus+grafana请，要不手动打日志看耗时也行。
顺带看下资源是不是满了，比如cpu

你们说的那些工具我没用过，暂时也不好在项目引入其他，了解到springboot有自带的stopWatch，就用了它来计算了各部分耗时。
cpu资源我是知道绝对不是满载的，因为压测同时干别的事时没感觉异样，这是压测过程中的cpu占用：


然后计时的结果以及压测的结果如下：


可以看出，至少在orderService的createOrder方法中，耗时是正常的。
然后我又试了试在orderController中计时，看看调用orderService之前的耗时情况：

这是第一次和第二次手动下单的情况，第二次比第一次在controller处省了些时间，说明token的缓存起了作用。

然后压测结果：

似乎controller部分也没怎么耗时。（比较奇怪的是，controller处打印计时和service处不是一一对应的，是jmeter压测的原因吗）

现在给我的感觉就是，Java程序部分似乎是正常的，时间也消耗不多，但是压测结果就是这么让人失望。如果这个问题悬而未决，感觉后续也优化不出啥名堂来

JennyFaceOff

super_uni 发表于 2022-11-25 00:37
localhost？本地压本地？你得看看cpu是不是爆了

— from OPPO PEGM00, Android 12 of S1 Next Goos ...

今晚试的发在16楼了，能不能帮忙看看？cpu占用不高

JennyFaceOff

紧那罗 发表于 2022-11-25 10:38
本地压本地确实不是理想的测试环境

另外我觉得没学瓶颈分析空学调优是根本问题

最新的发在16楼了，本地压测本地也是无奈之举，但是之前试过压测“商品详情页”，虽然页面只有MySQL的读没有写，不过在线程和循环更多的情况下可以达到5、6000的tps，每次优化都可以看到提升。所以感觉也不像是线程太多之类的问题，可是压测这个交易功能就是效果不见长进，让我这个初学者感觉邪门。

char1st

jmeter线程组怎么配置的 ，还有springboot的线程数，能贴下么？截图看CPU还是很闲。  或者可以简单试下ab或者wrk这些工具。 说实话个人做压力测试就是图一乐。

JennyFaceOff

char1st 发表于 2022-11-25 20:32
jmeter线程组怎么配置的 ，还有springboot的线程数，能贴下么？截图看CPU还是很闲。  或者可以简单试下ab或 ...

楼里之前这些图片都是本地压测的，所以.properties设置和虚拟机部署的不太一样，刚刚打开4个虚拟机又试了试压测，效果还更差一点（tps稍低，会出现小部分connection reset的报错，如前面说的）。
jmeter线程组是这样设置的：


springboot线程数是这样的：

我刚才发现，相比Windows的部署的压测，压测虚拟机的时候jmeter右上角的线程数似乎没有跑满，比如1000个线程只有300多个在跑搞错了，确实线程跑满了，而Windows时似乎基本跑满。然并卵，压测结果都很一般。
另外我还有个问题想请教，我看课程视频时他刚开始压测的时候平均响应时间和我差不多，但是吞吐量比我高不少，这难道是我同一时刻实际处理的请求数更少的原因吗？

pyjq

我在优化前压测200个线程也是200多tps，平均响应500ms左右；结果优化后还是200多tps，响应时间也没啥变化。

响应时间没变化的话，请求增加的情况下tps怎么会不变呢？是不是jmeter有问题？看错数值或者哪里的设置错了？

dada

看上去有点像内部端口耗尽，可以看下单交易时间是不是损耗在建立连接上，或者直接看下系统内部端口号释放是不是正常。

JennyFaceOff

pyjq 发表于 2022-11-25 21:36
响应时间没变化的话，请求增加的情况下tps怎么会不变呢？是不是jmeter有问题？看错数值或者哪里的设置错了 ...

这个我也没搞明白，优化前和后都用过两种压测参数，一种是200线程，ramp-up时间为5秒，循环20次，一种是1000线程，其余一样。
下面图片是优化后的程序，两种压测参数下的结果：
确实吞吐量没啥变化，可能因为平均响应时间倒是真降低了。

zxc111

先整个基准测试吧，新起个纯静态页面压一压看能到多少，如果这样都不符合预期那就检查各种配置吧。然后分别压sleep10ms,50ms,100ms等等，看相同资源同样tps用的延迟是多少反推你的耗时大概是什么程度。资源没打满首先说明还有很多可以提升的地方，除非io瓶颈了

----发送自 OnePlus KB2005,Android 12

JennyFaceOff

dada 发表于 2022-11-25 21:49
看上去有点像内部端口耗尽，可以看下单交易时间是不是损耗在建立连接上，或者直接看下系统内部端口号释放是 ...

这个部分是知识盲区了，感觉不知道怎么解决，可是之前压测商品详情页时有更多请求也没有这样，是因为那个是GET而现在是POST吗

dada

JennyFaceOff 发表于 2022-11-26 13:14
这个部分是知识盲区了，感觉不知道怎么解决，可是之前压测商品详情页时有更多请求也没有这样，是因为那个 ...

猜测部分属于猜测结论不用细究，现在主要是看清楚现在的响应耗时里面占大头的到底是哪块，看你服务端日志耗时整体是很快的，远低于jmeter检测到的结果，那就要搞清楚那部分时间损耗到底在哪里。如果有loadrunner之类的工具是比较容易看细节的，jmeter不知道有没有类似功能。现在看你调整几次的观察数据猜测的话就2个方向，一个是jmeter遇到啥瓶颈了导致实际没产生足量的压力，或者jmeter请求服务的时候建立连接花了很长时间。导致问题的可能性很多，要更多的数据才能进一步分析。

JennyFaceOff

董卓 发表于 2022-11-24 22:43
抓个javacore，拉个flamegraph看看有什么预料之外的热点
上arthas看看也行

这两天有其他事耽误了一直没搞，今晚本来打算用flamegraph的，但是windows performance analyzer下载了不会用，虽然用windows performance recorder录了一段，可是那是包括所有的进程的，实在看不懂。

本来差点想放弃，但寻思jmeter也是java程序，于是试了下arthas，虽然也不太会用。我用它来看了下我springboot程序的部分，只看了OrderService的createOrder方法部分的trace。压测时候的结果是这样的：
但是我是在最开始选择的时候选择了第3个也就是我的springboot程序，而非jmeter：

这个jmeter下面也有很多的类，如果想用trace命令除了要知道类名还需要知道调用的方法名，可我不知道jmeter中的什么方法调用了我的createOrder。
还试了试dispatchServlet的trace *:

不知道这个能看出问题吗？

我对arthas实在不熟悉，搜了一下也没看到怎么样找更上层的调用。请问有办法做到吗？我希望能从jmeter压测的堆栈最开始追踪

wpwing

最直接的办法打log，在可能耗时的地方都打上，测试的时候先缓慢增加次数，然后把日志抓出来看

  -- 来自 能手机投票的 Stage1官方 Android客户端

JennyFaceOff

wpwing 发表于 2022-11-29 04:56
最直接的办法打log，在可能耗时的地方都打上，测试的时候先缓慢增加次数，然后把日志抓出来看

  -- 来自  ...

你可以看看我16楼和30楼的后续，至少在Java程序那一块的用时是不高的。所以我想从jmeter的调用开始找原因，可是我不知道arthas怎么找父调用，我想看看jmeter这个java程序是怎么调用压测的，以便看出完整的用时分布？

紧那罗

你的优化目标 是你的springboot程序 而不是jmeter。

—— 来自 HUAWEI JAD-AL50, Android 12上的 S1Next-鹅版 v2.5.4

cstljn

个人判断，jmeter造成结果失真的可能性较大，jmeter很容易受到发起端本身性能或环境限制，比如io限制或端口耗尽。你可以考虑装个skywalking对压测过程进行监控，比较容易看出瓶颈点

JennyFaceOff

cstljn 发表于 2022-11-29 14:35
个人判断，jmeter造成结果失真的可能性较大，jmeter很容易受到发起端本身性能或环境限制，比如io限制或端口 ...

之前我用课程提供的代码替换我的代码试过了也没好转，看来可能真如你们所说是我本地压本地的jmeter的问题，恐怕发现了也不好解决，我决定不纠结了，先往下做再说。