plantegg

java tcp mysql performance network docker Linux

王强2012在北大的演讲——读书毁了我

视频版本50分钟,不含问答,建议看文字版,这是视频: https://weibo.com/6033438343/Nxw2Fj2oN?pagetype=profilefeed

我为什么要发这篇

到处都是私域、卖货、视频等,好的文字不多了,这篇对应视频的文字版找起来不容易,所以特意在我的博客上备一份(我的博客极少极少极少发别人的东西),也希望你备份一下。

王强是新东方合伙人,口才一流、演讲技能一流,当脱口秀看吧。

我就只能羡慕这种智商一流的人,这人智商在北大里估计都是前10%,而你我是北大都考不上的,所以他说的方法你就看看好了,不适合你,但值得你从中间提炼适合你的不分,读经典拿书,读不懂就不要像他一样死磕,找些浅显的、增加你经验的书先看看,回头再来读经典

但大多时候我们都不知道哪些是经典,对别人是经典对你还是经典吗?

这人是个程序员,学了C 和CPP,对你有点参考意义

在我的知识星球就一直强调:不要跟着信息流跑,多去看最早发表的东西(多年沉淀的干货等等)

image-20231219105757910

下面是正文,扯淡栩栩如生,那不是重点。我就不给大家划重点了,都是重点:) ,文字版来自这里:https://book.douban.com/review/10286767/

演讲正文——读书毁了我

王强:谢谢小平。因为小平在读书上花的时间比较少,因为我都替他读了,他只问我结论是什么,他的知识并没有落后,而我视力在衰减。当然老俞,当年我引他进入读黄色小说的境界,至今老俞还不肯自拔,他是黄种人的代表,所以他成功了。作为人生,我今年51岁,我和老俞同年同月生,不是同一天,也不是同一个地方,因为老俞比我大一周,小平比我大六岁,是我的兄长,当年克强同志是北大团委书记,他直接受克强同志领导的北大团委文化部部长,我是直接受徐小平同志掌管的第一任北大学生艺术团团长,我当时管的是英达、英壮这样的人。而俞敏洪是北大最有特权的艺术团的观众,因为经常拉幕的时候缺一个人,我们说老俞能不能帮帮忙,老俞说能让我看吗,我说当然。所以从此老俞锻炼了强大拉幕能力。所以任何细节不要忽略,都是人生。

我今天想跟大家分享为什么读书在人的生命成长中非常重要。我这个题目叫”读书毁了我”,很多读者没看到这本书的内容就开始评论,说我是标题党,撒狗血。我说不是我撒,因为当年我的很多文章结集的时候徐晓,她是中国最伟大的女编辑之一,被称为京城四大美编,美女编辑。当年我说马云怎么有领袖魅力,他有领子有袖子,但没有领袖魅力,走到街上城管一定第一个扑向他,因为连人长的都不一样,像是从外星回来的,而俞敏洪长的就跟季羡林一样,就像去外星的人。小平虽然是天使,但是从体重来说,给他四双翅膀他也飞不起来。所以人啊,当你不知道要做什么事情,当你做的事情不能带给社会意义的时候,当你做的事情的意义不能给人的生命产生共鸣的时候,你的存在实际上是被人忽略的。

我现在自豪的是,我现在经常回忆,北大这个地方怎么产生企业家?因为我是内蒙古来的,我以为是学术的殿堂,清华可能产生企业家,因为他们搞科技,高科技,北大当年我们就是精神自由的三角地,都是自焚的地方,它只是结束肉体的地方,让灵魂再生的地方,从来不是做什么上市,这些好象与北大没关,但是人生经历这么多年,我发现北大为什么产生这样的人。

我就拿32楼举例,我们住的16楼没了,当时我和老俞作为北大年轻教师住在16楼,但是拿32楼文科男科楼讲,当时北大英文系来说,我们住在二层,这些年一过,发现诞生一个伟大的企业,那就是在教育界的俞敏洪为代表的新东方。再往第三层,我忽然发现当年有一个来自山西的青年,天天在水房里光着上半身,一盆冷水浇下来,唱着夜里寻他千百度,你在哪呢,天天念百度两个字,因为他是北大图书馆系的,后来诞生了百度李彦宏,当时哪能想到,因为从任何知识储备,他不能做企业,他不仅是学图书馆系,而且专业简直离成功太远,他是古典文献编目专业,清朝以后的事他都不管了,他直接奔甲骨文去了。所以他天天念where are you,那时一下雨雨水就没过膝盖,当时找不到了,where are you,搜索就开始了。

再往上走,四层楼住着北大中文系的,当年都是产生愤怒诗人,连名字都是愤怒的不得了,黄怒波。这么多年刮目相看,他要买下冰岛,他成为了中坤集团的创始人。更匪夷所思的是,北大中文系的女生楼里出来一个长相非常平和的人,她充满着激情,最后由于自己解决终身的情感问题,她就是后来创造了世纪佳人。这些人,是中文系的、图书馆系、英文系,这些与金融、融资、管理完全没关,但是我后来想怎么会出现这么一些奇特的企业,由这些人做的,我就想到北大给了一个东西,就是怎么样塑造你生命的东西,那是对知识的渴望、饥饿,超过了性本身。当年我们对性的渴望,但是校规非常严格,同性只能找同性。但是我们还没有得到同性方面的启蒙,当时洗澡堂,一个水龙头下,十个男生光溜溜的彼此互帮互学,那一个水龙头下十个手,像董存瑞炸碉堡的感觉。

但是我们就这么过来的,为什么我发现北大这个氛围是崇尚超越世俗吸引力的更伟大的东西,那就是对知识的诉求。我不知道你们现在读书状况什么样,整个八十年代北大最神圣的地方两个地方,一个是厕所,一个是图书馆,图书馆从早上六点,如果你不能到达写着邓小平题字的北京大学图书馆下面排队,你这一天与图书馆的座位已经无缘了,所以大部分人凌晨四点就起来了,然后带着一个冷馒头,从厨房吃剩下的或者从同学那偷来的,俞敏洪经常偷我馒头。然后借一堆书放在这里,睡也睡在桌子前面。所以当年读书氛围非常好,如果市场上出现一本书,你如果去晚了根本的得不到。我在中文系选了中国现代文学史,第一次讲到围城,我赶快到北大图书馆,没下课我就去了,但是没想到没了,结果等到快毕业的时候我才借到这本书,这就是当年北大的状况。而正是这样,读经典,读那些能够改变我们生命轨迹的那些书籍,成了北大人最后离开校门走到世界,不管你走到哪个领域,最后比别人走的稍微远一点的保证,因为那些书不是字,它也是生命,而这些生命比起你自己的生命来说,它能引领你的生命,它能型塑你的生命,所以我说这个世界上只有两种文字,一类文字是文字垃圾,(Informed )随处可得;但是有一类是非常好的,(Form you )就是它能够把你变成完全不同的另一个。所以我这个书题目叫读书毁了我,当年起的时候,徐晓给我提的题目,说这个题目在她心中好多年。她说你这个文字挺适合这个,我说”读书毁了我”,这个东西大家看到以后会非常奇怪,怎么会毁了你吗?她说毁就跟北京人说的,一团泥逐渐成型,就成了崭新的东西。我想如果毁用在这个意义上,它必须能够彻底摧毁你旧我,过去的我,狭隘封闭的我,然后诞生一个崭新的、开阔的、阳光的我,那读书就全部有了意义,这也就是当年北大为什么那些人天天想到的不是世俗的追求,但是到了世俗里一看,稍微一动他就得到了所谓世俗追求的东西呢?我觉得这是北大给了我们吸取信息的能力,分析问题能力,所以我今天想跟大家分析分析读书。

我当年在新东方接受采访的时候,我说要读书只读一流的书,做人只做一流的人。为什么这么说?因为现在信息充斥的海洋里,我们人生有幸,但是我们要读的接受的信息太多了,如何辨别书?什么东西该读呢?跟大家分享一下我读书的选择,第一,畅销书我坚决不读,不是我牛,看不起畅销,因为我知道我生命有限,已经51岁了,再向苍天借30年,我已经80岁了,所以我还有30年读书的时间,我只能读人类历史上没被大浪淘沙过的东西,所以我现在读书越来越往前读,中国的典籍越读越遇到先秦,西方也顶多读到二十世纪中叶,因为我觉得那个时候的人,他们创作文字,他们的文字是他生命的写照。比如说现在翻译小说,坦率的讲,我只选择那些真正的以生命完成一部译作的大家们的作品,哪怕这个作品并不时髦。比如说《悲惨世界》,李丹翻译,本来他可以成为另一个徐悲鸿,但是他们放弃了,几十年如一日,文革如此惨烈,李丹最后剩几卷没有翻,他的太太继续翻,这本著作我是一读再读。像朱生豪翻了27本莎士比亚的剧,但是你现在再读任何一本,哪能找到朱生豪当年用汉字表现出的莎士比亚。所以我常常更小平说,有一天我们一定要拍朱生豪的电影,这个电影叫做《莎士比亚在中国》,如果没有朱生豪,全世界四分之一的人不会第一时间知道还有莎士比亚,所以莎士比亚的墓地应该旁边有一个朱生豪的碑,多么伟大,四分之一的人口是通过朱生豪第一时间知道的英国还有一个莎士比亚。

所以我觉得读一流的书就要衡量,这个作家进入书前的状态是什么?他是为了满足市场的需求,所谓市场的利益,还是他倾其鲜血、生命和经历融入的东西呢?坦率的讲,我在北大整整呆了十年,做了四年学生,当了六年老师,离开的时候是英语系的讲师,当然我的宿命也从此定了,只能讲,没当教授,坐不下来,更没有博导那个肌肉。但是我作为见证,俞敏洪、小平他们当年都是如饥似渴的在读书,尽管领域不同。老俞主管肉体,小平是超越肉体和灵魂的东西。当年小平是我们当中第一个出国的,我记得那天下着毛毛细雨,小平当年住在北大小院,32楼前面的一个小院,最早北大出版社的地方,他住在那里,因为他是团委干部,所以有四合院的那种感觉。那说要离开了,要到美国,然后到加拿大去追求他的音乐梦,我就知道,他当时为凑足他的机票,他珍藏了作为任何一个学生很难想象的格罗夫音乐辞典,到处拍卖,他希望获得飞到美国的机票。他终于卖出了,用一半的钱请我在西门一个火锅店吃了火锅,最后大家挥泪离别,从此我步上小平的后尘,我也要到国外去,老俞也想步我们的后尘,但是国外暂时不需要他。

为什么读经典能够改变我们呢?文学的功能是什么呢?在我看,文学的功能就像我在序里说的,如果一个真正有力量的文字,它一定是能够对我们的审美产生奇异的再造,它对我们对真的追求有奇异的启示,它对我们对善的追求有如饥似渴的充电的感觉,所以我们对人类最高的价值,真的、善的和美的就会变成我们的血液,一旦人身体里有这三样东西,你在社会上走向现实中,你就不会轻易的被世俗的所谓流行的价值、暂时的价值,甚至非常糟糕的价值轻易扭转。我的这个读书基因从这开始,从我中学,我分两个阶段,一个是中学,一个是北大。我之所以能进北大,一半我认为是老天眷顾了我,因为大家知道,我是第三届大学生,小平是第一届,克强是78级,克强比你低一级,但现在比你高很多级,这就是人生最后不一样的东西。所以人生,体重太大,最后他也走不太远,所以大家现在要减肥。

高中我是来自内蒙古,我们那个学校在当地有一个叫包头的地方,都不算是优秀学校,但是为什么我能够走进北大呢?我忽然怀念起我当时在高中遇到的一批中国我认为最顶级的老师,为什么这些老师会到包头呢?感谢文化大革命,全是右派,一个一个发配到包头,结果被我遇上了,他们教会我全部的东西都是以他们各自的方式告诉我,真的、善的、美的,一定是从那些流传在人类时间长河里面没被淘汰的文字中,存在那里。你如果不断的在这样的文字中熏陶的时候,当你离开这些文字的时候,这些文字就变成了你的世界,所以从单词word到world中间只差一个字l,这个L,这就是文字、阅读和真正人生世界的完全最简单的逻辑关系。如果你读到的不是真文字,你遇到的不是真语言,你最后见到的一定是虚幻的世界,不是真实的世界。这也是为什么读书真正要对你产生作用,会产生什么呢?它一定要和你真正的生命融汇在一起,而几千百年来,没有被淘汰的著作,因为一代代人如果都这么选择的话,你一定要相信人类的选择,而不是现在市场的选择,更不是广告词的选择。所以这是非常关键的,我在序言里提到,去年我写了一篇文章,其中谈到葡萄牙诗人佩索阿,其中有一个诗写的是小河和村庄的关系,点清了我心目中文字怎么和你生命世界在一起,它必须对你生命产生极强的冲击,这个书才值得读,或者你真正领悟这本书,所以他的诗也是我从英文翻译过来的,他说,塔古斯河美过我村庄的那条小河,但是塔古斯河又美不过流进我村庄的小河,因为塔古斯河不是流经我村庄的小河。太美了,为什么?文字如果不属于你的村庄,它不能流穿你的灵魂,这个书不值得一读,而真正传统的经典有穿透生命力的这种力量。

我回到高中,我怎么认识到什么是一流的书呢?随便举个例子,我感谢文化大革命,把这些有文化的人推到内蒙古这个没文化的地方,教我古典文学的王传真老师,现在这些老师全都去世了,包括我大学的老师,大部分都已经不在了。但是这些高中老师教我古典文学的王传真老师,我第一次上他课的时候忽然发现什么叫大师,王老师告诉我们去新华书店买《古文观止》,中华书局第一版的。然后他说,你们要听懂我的课,这个假期必须做一件事,买来这个课本,他不讲,他拿出一套油印印出来的厚厚一叠古文,标点全部隐去了,他说你们这个假期玩完了以后,你就去读读我这个自己刻印出来的东西,然后按照你全部的理解,使出你全部的工具来给这些文章,按照你的理解给它们加以标点,我们在没有走进古文的世界,这个东西既刺激也似乎不可能,但是我为了下学期听懂王传真老师的课,我从我爸箱子里翻出他爸给他留下的当年最老版的辞海,我开始一个一个的,每天以十个字的速度往前运行,整整三个月我没干别的,因为越往前走越觉得这里深不可测,但是我的梦想是一定要听到王老师的讲解,因为这是他对我们唯一要求。结果就乱标点,但是我一天以十个字的功夫不断的往前进,最后50篇文章被我标点了。等到王老师到我面前给我面试的时候,他随便说了几句,我基本背出来之后,他说了两点,第一,你的标点全错了。第二,孺子可教,因为你全标了,就是你这个努力,我觉得可以。其实当老师,有的时候非常充满智慧,我们的胡校长胡适,胡适不判作文的,他没有时间,他有时间要搞新文化运动,作业算什么。但是据说,上作文的课每次都能给出学生成绩,后来据他的学生回忆,胡适判作业那是胡判,他今天晚上吃完饭,收了几十份作业,你写了文章,他开始把桌椅放在离靠门半米远的地方,泡一杯清茶,然后扔作业,哪个扔的最远最高分,为什么?写的多,不管你写的怎么样,你下了苦功。别人一扔不远,零分,写的不多。扔的远,够份量,一百分,胡判定就要开始出来。

而且我当时,我怎么走到英文这个道路上,一流的书上来直接读《古文观止》就可以了,看似很艰难,但是读完全部启蒙的古文书,我再读人教的那些太简单了,因为你的制高点不一样,一流书、二流书、三流书区别在这。比如英文,老俞就没有遇到我这样的老师,今天还说着印度人非常理解的英语,但是到了美国就崩溃了,因为他是印度籍的移民。我这个英文老师学俄语,英文不太懂。但是这个老师一片真诚,他知道该给学生什么样重要的价值,怎么让英文走进你的生命。上了他第一堂课,他觉得我的两个眼睛不断的盯着他,两耳竖着,像狼犬一样,他说你真心想学英文吧?我说当然,上您的课厕所都忘了。他说王强你到我办公室。当天下午在他办公室他说了一句话,他说从此你要上我的课。我说老师我就想学英文。他说我教不了正经的英文,我的底子我自己知道,你要想学真正的英文,我给你想办法,你就不用上我的课。第二天下午4点,下了自习,他把我叫到他办公室,从黑皮兜里掏出旧报纸包的东西,把慢慢打开,一打开,我一看,是一个断了一角的黑色的绞盘,唱盘,叫LP,大唱盘,你们现在连CD都不用了,那个大唱盘这么大,他说王强你要跟这个学,这是什么呢?这是我从废品站几年前搜集到的东西,它是BBC英国广播公司出的一套经典英文教材,从明天起,每天下午四点你只要答应我一件事,不要回家,来跟我学。后来我就非常兴奋,第二天我拿到这个光盘以后就跟着他,他把我领到学校的广播间,那时候他把团旗往窗户上一盖,门外面挂着闲人莫进,正在录音。然后他用当年我们中学唯一的手摇唱机,跪在地上,他一边给我摇,一边让我赶快重复,而且说你这个课本永远在我手里,等到你全部的课本能够背答入流的时候,你就成就了。结果他做了一件事,每个礼拜都这样,最后倒背如流的时候,他把这页撕掉了,所以我这个课本越学越少,最后只剩下封底的时候,他说王强你可以毕业了。我忽然意识到,我离开了文字的课本,但这些东西全在我身上,所以等到我到北大,作为英语系的学生第一年入的时候,在我们班50个人中,只有我说的着流畅的英语。为什么?他们不知道来自一个内蒙古包头的,别说英语,汉语都不沾边际的,说蒙古话的人,能说如此好的英语。其实我没有学任何东西,就是破唱盘和破唱机,一摇、一摇,摇过了一两百页的篇幅,这些篇幅被老师扔进垃圾堆的时候,我发现他让一流的英文教材完全引入到我的灵魂中,我感谢他。

教我历史的老师让我有了进北大的冲动,为什么?他是南京大学太平天国专业毕业的,学了五年,最后被打到包头,他讲历史,我听的如痴如醉。这个老师爱流鼻涕,历史长河,源源不断。而且这些老师,我不仅跟他们学读书,我从他们做人也学到了品性,就是一个字-真,最崇尚的就是真。这个老师非常有意思,他看我非常好学,他希望我每个礼拜三天到他家,那时候肉是供应的,那时候我已经是中学学生,老师为了让我安心在他家读历史著作,在他的引导下从《左传》开始,一篇一篇给我解释,每个月他家四个人,一人二两肉的份额,炒完以后只是我俩来分享,所以我非常歉疚。他说王强你要学好知识,肉体先要活着,他说我觉得你是可培养的,他展示了一流思想和一流文字真正的胶合。他上课非常有特点,从来不备课,这样一个顶级的老师,在我们学校从来没评过优秀老师,所以优秀是靠你真正生命才能支撑的。而且这个老师从来不服学校的规矩,从来不备课,他觉得跟其他老师没法备课。我记得每天早上九点都是历史课,大冬天穿着棉袄,历史书插在裤腰上,带着历史的温暖就进来了,而且第一个动作就是背向我们,掏历史,那是他的故事,他对知识如此娴熟,书没有打开一页,因为历史都在他的心里。而且他讲任何一个孤零零的事件都要放到更大的范围,讲完五四运动,他一定看看亚洲在干什么,欧洲在干什么,全世界在干什么,我们通过上中国史已经连通了世界,从此我才知道原来读懂中国史必须放在世界历史的框架中才可能。这样的老师简直让我叹为观止,就是他一句话让我升起了北大梦。他说我这个岁数这辈子实现一个梦想没戏了,什么梦想呢?他说我是学历史出身的,但是我对历史上的宏观描述,社会主义、共产主义的发展描述我有疑问,什么是社会主义,什么是共产主义呢?当时国内翻译说,社会主义是各尽所能,按劳分配的社会,这里各尽所能,但是按照你能够多做多得,能够给你分配你应该得的东西,这是社会主义分配原则。共产主义当时分析说,各尽所能,按需分配,他说同学们,作为我一个学历史的人,我的历史意识告诉我这个翻译不精准,如果共产主义和社会主义,一个按劳分配,一个按需分配,都存在”分配”的话,这两个社会没有区别,按照我的理解,那个时候人类精神极为发达,那个世界应该是各尽所能各取所需的时代,你自己决定你贡献什么,你拿回什么,这才是他向往的共产主义,和社会主义你需要我给你,不需要我不给你,这个没有什么本质区别他。他们说你们将来如果报答我作为你们的师恩,你们如果想学外语的话,读读马克思的原典,告诉我这个是不是对。八十年代的时候,所有发达国家,最后管理这个国家的都是学文的,学文的人可以看到全部,甚至看到没有存在的东西。所以你们学文的人应该比学理的更加聪明。后来我带着这个准备报考北大中文系,因为当时我的作文非常好,他说王强你千万别报北大中文系,你的中文已经完全达到了自学成才的程度,你将来要毙掉所有北大中文系的学生,你只需要一个东西,比他们多学一种语言,就这句话让我改了志愿,变成了英文系,因为老师告诉我,你看世界要多一种语言,你的世界就会宽广一下。

就是这样,我最后终于改换了志愿,到了北大英文系。我到校第一件事就是搞清楚,马克思论断是不是我的老师想像的,正好朱光潜先生翻完经济学手稿我一看与我老师的论断一字不差,社会主义分配原则是各尽所能按劳分配,共产主义一定会达到人类精神高度发达和自由,然后各尽所能,各取所需,我告诉我老师消息的时候,他说你真是我的学生。就是这样一个老师,他让我知道,历史你要读懂要站在什么高度。

再讲一个例子,教数学的老师,南开大学数学系毕业,我当时非常讨厌数学,我喜欢文,我们班一大半学生学不懂数学,但是只有这个老师的课上没有人上厕所,为什么?他对数学知识的了如指掌,比如他讲几何,他只带三只粉笔,从来不带教具,他要画个圆,先点圆心,往后一站,再往上一扑,动作一点都不停,你下课以后发现这个圆在哪衔接的不知道。他说画40几度角,他画完以后,很多学生下来拿两角尺去量非常准。所以后来上他这个班的学生,连不喜欢数学都要盯着他,因为觉得这是艺术课,结果这个班最后90%多的人都进了理科大学。当时令我难忘的是,八十年代,那时候我记得是考大学前一年,出来一个陈景润,数学家,非常伟大,突然光明日报第一版发了《哥德巴赫猜想》,当天下午我平生第一次知道有讲座的形式,说让大家带着板凳到操场上听讲座,讲《哥德巴赫猜想》,前面部分讲什么是哥德巴赫猜想,第二部由讲汉语的老师讲这个报告文学为什么是优秀的报告文学。结果我们坐着小板凳,太阳底下,第一次听什么叫偶数等等,听完以后没听明白,但是觉得陈景润很伟大,后来我的数学尽管是考文科的,那年我还考了59分。我们那年,80年和你进清华是同样一个卷子,77分就可以被清华大学数学系录取,我们59分,我们这是参考分,但是俞敏洪参考分0分,太悲惨了,一点没参考价值。

就是那个东西把我引到数论,所以在中学时我就读华罗庚、王袁的这些论著,懵懵懂懂,试图要读点爱因斯坦的著作,而且读了徐池报告文学我知道优秀报告文学是这样产生的,以后我也写了无数的小的报告文学,结果没有一处发表,所以到了北大之后我一直想写诗,我的诗集叫《野性的14行》,俞敏洪最后也写诗,他是北大最后一个没有自焚的未遂诗人。我们当年带着这个,知道了各个领域,要想走进这个领域,必须站在最高的地方,当时至少最优秀的地方我才能一览众山小。

到了北大更不得了,因为我们见到的那些人,都是大家见不到的那些大师级的人物。比如我是英语系的,英语系所有泰斗都是直接教过我们的,像李副宁(音)先生,不论刮风下雨,李先生的裤脚总是捻上来,一尘不染,他总是提前五分钟走进教室,也是把新概念往上一放就侃侃而谈,上第一个星期我们忽然觉得,每次上完课李先生这四块黑板没有擦过一个字,但是他写满了,在往下一周忽然发现,每当李先生写到这的时候,我们能推算出什么时候下课铃响起来,这真是大师,所以我说我将来当老师一定要当李先生这样的老师,他是中国英语教学的泰斗,像当年朱光潜老师,操着一口安徽桐城话讲什么是美学,尽管我们听不懂,他的桐城话非常难懂,但是就是在这样的情况下,我们看着朱先生最后完成了他的一步一步伟大译作,在他生命走到90多岁的时候,还每天馋着拐棍颤颤巍巍的到北大图书馆完成他的最后一部译作《新科学》。

这些老师给我们震撼如此之大,所以我们一下子扑到了北大的读书氛围中。他们给我们开了全部的书单,都是人类历史上经典的东西,因为他们说过,如果你没窥探过人类过去的最高的封边的时候,你就不知道你现在站到的地方究竟离海平面多高。所以当时所有教授都跟我们说,要读那些真正经过时间考验而不被淘汰的东西。所以在北大我的读书激情一下子被点燃起来,当然俞敏洪也被我的激情点燃起来了,但是俞敏洪呢,他当时基础稍微弱一点,有一次他得了肺结核,他住在西边享受那个传染病院,我去看他,他说王班长,我是他的班长,他是我帮助的同学,我们班四年始终保持倒数第一的同学,底子非常厚,这种人一站起来非常稳的,你想连续四年保持不变,倒数第一,太难。他说王班长,你从北大寄给一本莎士比亚的14行诗怎么样?我记得我回去以后给他写了长长的信,大概50多页,最后结论说,老俞读书要从基本功抓起,你一年以后我再替你借莎士比亚14行,至今老俞没读过14行,但是他用人生写出了15行。所以这就是当年我们在北大读书的氛围,就是读这些经典,人类熟悉的,甚至很多人追求时髦不屑一读的东西,对我们的生命,对我们的审美,对我们对真理的理解和渴望,对我们对语言和世界的关系,以及型塑生命的力量有了直接的感觉,就是这样一步一步推着我们走到今天。无论我在北大当年教书的时候,还是到了美国,还是从美国回来,我的读书的这个激情,选择所谓一流书的概念一直伴随着我,所以我认为我人生最大捷径就是花了时间非常痛苦啃了一流的书。举个例子,当年我到了美国,我改行,我不学英美文学,因为我发现到了美国来错地方,不能在美国生存,我学了十年的英文,在美国一点用没有,我不能教美国人英文来生存,那是李阳要做的事。我知道在美国生存要有一个技能,就改成计算机,但是学计算机谈何容易,计算机在八十年代是第一代计算机时代,主机,主机两个特点,体积庞大,造价昂贵,一台上百万,当时直属教育部重点院校才拨一台,安放在北大的南北阁。那个时候特别羡慕计算机系的,因为只有计算机系当年在北大四年,他们有一方面特权是任何系没法超过的,就是洗澡,到洗澡堂,计算机系人优惠洗澡,为什么?他们要消毒。为什么消毒?因为计算机如此昂贵,发展初期人们搞不清楚计算机病毒是怎么出来的。这个也应该拍成电影,北大当年就两个澡堂,一男一女,我们当时分的非常清楚。老头老太太管的非常严,比你们现在门卫森严多了,不仅要有洗澡票,还要有学生证,两证具全才能进去,而且还要看哪个系。你说哪系的?中文系的,明天再来,今天比较紧张。那个人回去了,一看哪个系的?计算机系的,赶快进去,今天你们是专场。另外一个,刚打了篮球,老师我必须洗,晚上要跟女朋友约会。老师说拿出学生证,考古系的,捣什么乱,明天也不要来,他们只有校庆的时候才能来,这才代表北大的历史。所以当时我觉得世界上两个东西我没见过,一个是上帝,一个是计算机,我到了美国学了计算机,我崩溃了,但是我想到老师教我的读书,为什么崩溃?因为到了纽约州立大学,录取我很容易,我记得第一堂课让我崩溃,第一堂课上微积分,十年我没摸过数学,上来我就危机了,就分裂了,而且讲课的是印度籍的老师,我想当时在北大练听力怎么没练过这个东西呢?所以同学们,学习不一定标准就是最实用的,我崩溃了。而且这个老师头上缠了发黑的白布,我听的越来越崩溃,我多少次想冲上去问他,你也是人,我也是人,咱们俩怎么这么难沟通。后来我想到,什么叫君子,该动手的时候不动手,该出手的时候不出手。

我想,我作为北大六年老师,我也没白练啊,我赶快到书店拿下计算机两本一流的著作,学西语言,上面有几百种西语言,但是我找到薄薄的不到两百页的著作,我不断的在读,不断的读,又不像我北大读经典一样,这本书我最后读的基本上找不到页玛的时候,我忽然发现我对C语言找到奇特的理解,我知道它为什么诞生,它优越在哪,它比较其他的语言,比如纯粹的学术语言,比较机器的语言,它好在哪。后来我学C++语言的时候我又找到了发明C++语言写的东西,看似非常精简,因为在他来说都不是问题,仍然不到两百页的书,我苦读整整一年,最后忽然我对这之间的世界完全了如指掌,最后我是我们班被老师评价为优秀的学生,当你熟悉一种语言的思维方式的时候,你很难跳到其他世界,因为是完全不同的,他是解决C不能解决的问题,而我由于掌握全部一流的平台,我非常正确的走进了两条道路,而且走的非常正确,老师给我非常高的评价,这就导致了我后来在纽约州立大学,尽管第一学期几乎想要抹去自己,我常常说这哪能听懂,尤其是印度籍教授。我经常利用上厕所的时间跑到操场上想,上帝,你把我微积分了吧。但是这两本一流的著作,让我走进真正这两个语言思维的精髓,我后来一下在这两个中间,一旦跳跃,我就变成超越所有本科学生天天在市场上抓关于C++这个介绍、那个介绍,读十本书也没有摸到真正C++核心的东西,所以我的读书基因在美国又一次拯救了我,使我经过两年半的艰难困苦的努力获得了纽约州立大学数学系机系的科学硕士学位,是我们班第一个走进美国一家伟大的软件公司,叫做贝尔传讯公司,我完成了我的转折,后来才有了95年一天深夜,老俞一番鬼魅的电话打到了我家,我做了人生的选择,才有了三个合伙人的雏形。

这就是我跟大家分享的,读书要读一流的书,做人要做一流的人。谢谢大家。

提问

​ 主持人:感谢王强老师分享的读书经历,下面进入提问环节。

​ 提问:王强老师刚才说读书要读一流的书,做人要做一流的人,在您看来什么样的人才是一流的人?

​ 王强:第一,真诚。第二,有激情。第三,开放,对什么都容易吸收。第四,阳光,你如果自己自焚,你也让别人照亮。第五,要有梦想,而且为了梦想不断往前走。第六,在大是大非面前,一定要有原则,而原则高于一切,善的就是善的,恶的就是恶的,所以我们做新东方,我就是按照这样的东西走到今天,也面对老俞基本是这样,所以我在老俞面前随时就拍桌子,因为只要偏离任何原则的东西,所以新东方的人给我一个外号。

​ 徐小平:说王强老师叫做脆弱如钢,俞敏洪老师叫坚强如芦苇,我叫芦苇钢。王老师说的第一词叫真诚,有这样一个细节,俞敏洪拿着书说,你有一天会让我嫉妒的。当时我在加拿大学完英文硕士,做一个私人老师,非常不成功,回到新东方的时候老俞说了一句话,老俞说小平,你很快就让我嫉妒的,他把对朋友的一种赞美、认同表达出来。我们三个人在一起的时候真的是坦诚相见的,虽然我们从来没有在一起洗过澡,大家心里有什么东西说出来,所以新东方历史上所谓的争吵,恰恰使新东方成为伟大企业的真髓所在,有什么说出来。所以在合伙人里面,俞敏洪说过一句话,他说我们来美国之前,我们不是真吵,我们是不同观点、不同角度的交锋,是思想的汇集,所以你们今后做人要学会这种东西,就是真诚、沟通、交流。

​ 提问:我今天注意到俞敏洪发了一篇博客,特别澄清电影和新东方之间的差别,一再想撇清这中间的关系,我想听听您怎么说,您在单口相声当中总是把他当成一个捧哏,不断的调侃。

​ 王强:他现在也是这样,老俞看完这个电影说,这个主人公离我比较远吧,怎么没有雄起的时候,我说这个电影最大的意义就在这,连这样的人都能成功,别人更能成功。

​ 徐小平:这个电影,第一他没有参与,事实上是这样的,2011连的3月份,韩三平找我,要拍摄一般部关于中国梦的电影,然后我找俞老师,我说我来写,我在新东方一直负责新东方的宣传公关、企业形象、品牌建设、营销,当时老俞说千万不要写,后来我告诉韩三平我们不写了,他说不行,你不写我们就找别人写,你不写我们就把新东方写的很坏。事实上后来我用两个礼拜拿出那个剧本,但是既然俞敏洪不想写,就写了海归回国创业的故事,海归回国和两个朋友创办了英语学校,是一个爱情故事,后来陈导说新东方会不会告我们,我说这个片子如果出来不符合我们之间的价值观、我们的友谊观,我根本不跟你合作,一部电影算什么。一直到了11年的年底,他来找我,我是3月份写出来的,剧本出来以后,我把我的剧本寄给王老师和俞老师,我提供了最初在新东方的素材,我的剧本给你们看,我要经得起友谊的审查,而陈导的剧本要经得起市场的审查。等到最后电影出来以后,俞老师看完以后觉得我这么伟大的人物怎么写的这么窝囊。这就是电影的目的,如果你这样窝囊的人都能够做到这么成功,对当代青年是有意义的嘛。所以俞老师也就一如既往忍气吞声的接受了这个片子。

​ 提问:您刚才说一流的书,您给我们推荐一些一流的书。

​ 王强:一流的书很多的,但是确实很难,因为我也特别怕推荐这个书,如果读完以后跟你生命确实没有交际的话,确实浪费时间。比如对于西方文明史的理解,至少有几部著作大家一定要读,从文艺复兴时代就是博格哈特的《意大利文艺复兴史文化史》,但是荷兰大史学家写的《中世纪的秋天》,读完这两部作品你对中世纪文艺复兴的本质有非常好的了解。到了《历史的研究》,汉语翻了一卷的结本,这个是作者花了三十多年的时间,用五千多页的篇幅研究各个存在的文明形态,研究他们怎么繁荣消亡的,最后得出两个东西,所有文明符合两个东西,如何面对挑战和回应,所以读完这几个东西,从中世纪到文艺复兴,再到二十世纪人的历史,有了非常宏观的东西,按照他们所指引的方向再往近读。

​ 提问:我想问王强老师一个问题,我感觉王洋的角色是最温情的,最初他似乎是愤青,你在创业中是否也扮演这样的角色?

​ 王强:我在三人创业中更接近邓超的角色,前一部分挺像我的,小平这个角色也是相反,在新东方我称之为小平是最有远见人,新东方所有历史大发展第一启动者就是小平同志。但是小平的性格,我过于钢,我是直接和老俞yes or no,小平有一点像王洋那样的,你这拍两下,那拍两下。

​ 提问:在合伙创业过程中难免冲突的时候,每个人应该怎么做?

​ 徐小平:制度,议事规则。

​ 提问:是什么让你们最终要合伙的?是因为个人感情吗?

​ 徐小平:有一个学生转了我们三个人的照片,说他们三个人搞鸡搞了三十年。我想简单说,创业一开始,合伙人往往是互补,互相需要。如果能坚持到最后靠的是什么呢?共同的价值观。什么是价值观?什么东西最重要,当两个东西摆在一起,什么最重要,比如你爱上一个人,你妈妈说他不行,我们不喜欢,你为此让你爸爸妈妈难受,还是你追求你的真爱,这就是价值观。比如说新东方的价值观是什么,就是新东方这个品牌,我们对同学的吸引力,包含我们对学生的承诺,我们相信这个东西有价值,比起我多一个点、少一个点,一个点新东方能值五千美元,但是我们共同的把这个品牌做好做大,你的东西才用不完。所以新东方有非常杰出的人,他不认同这个品牌,他就离开了。但是我跟王强、俞敏洪,我们在最痛苦的时候都知道这个品牌是我们共同的价值观,新东方要把中国最优秀的人才,让他们看到另外一个世界,最终能够把中国这个世界变得和最美好的世界一样美好,我们完成这个历史使命。

​ 提问:我也是非常喜欢读书的,在看很多作品的时候本来就非常晦涩难懂,你刚才说你读很难懂的书的时候还反复读,我想问是什么样的心态让你读不懂还可以反复读。

​ 王强:书写出来的文字两种,有力量和没有力量。书有两种,一类是硬性的书,一类是软性的书,黑格尔、康德、尼采、柏拉图这些都是硬书,硬书你要想从中获得养分,唯有一个捷径,就是不断的读,因为你不可能靠一遍,畅销书一遍不用读完你就理解了,这些畅销书和那些真正书籍的区别。所以当你一遍一遍进入的时候……

time_zone 是怎么打爆你的MySQL的

基础知识

这篇关于time_zone 的总结写得非常好Time_zone ,建议先读完做个基础知识的打底

Mysql日期和时间存储数据类型

存储类型 存储值示例 解释 适用场景
Datetime YYYY-MM-DD HH:MM:SS 时间日期类型。DB时区切换它的值不时区相关常见名词解释变, 但时区切换后代表的时间信息已改变. 使用简单、直观、方便。适用于无需考虑时区的业务场景,例如国内业务
Timestamp 名词1547077063000 解释以UTC时间戳来保存, DB时区切换它代表的时间信息值不会变,但是会随着连接会话的时区变化而变化。 内部以4个字节储存, 最大值可表示到2037年. 适用于客户端需要支持多时区自适应的场景,因精度有限,不推荐使用
Date GMTYYYY-MM-DD 全称Greenwich Mean Time 格林威治(也称:格林尼治)时间,也叫世界时(Universal Time),也叫世界标准时间。是指位于英国伦敦郊区的【皇家格林尼治天文台】的标准时间,是本初子午线上的地方时,是0时区的区时。GMT格林威治时间可认为是以前的标准时间日期类型,不包含时间信息 不关注时区只需要显示日期的场景
Varchar UTCYYYY-MM-DD HH:MM:SS 全称Coodinated Universal Time 协调世界时,又称世界统一时间、世界标准时间、国际协调时间。它是以原子时(物质的原子内部发射的电磁振荡频率为基准的时间计量系统)作为计量单位的时间,计算结果极其严谨和精密。它比GMT时间更来得精准,误差值必须保持在0.9秒以内,倘若大于0.9秒就会通过闰秒来”解决”。UTC时间是现在使用的世界时间标准字符串类型,可以用时间字符串来表示日期时间类型,格式可自定义,如果用ISO标准时间格式存储,则可以包含时区信息:yyyy-MM-dd’T’HH:mm:ss.SSS+HH:MM 自定义存储日期时间格式,可包含时区信息,适用于只需要显示时间的场景,不方便计算
Bigint DST1547077063000 Daylight Saving Time的简称,又称“日光节约时制”和“夏令时间”,也叫夏时制。表示为了节约能源,人为规定时间的意思。在这一制度实行期间所采用的统一时间称为“夏令时间”,在欧洲和北美用得比较多数字类型,可以存储时间戳,表示某个时刻,稳定性最好 存储某个时刻,可以表达时间的确定性,存储/网络传输稳定性最好

时区相关常见名词解释

名词 解释
GMT 全称Greenwich Mean Time 格林威治(也称:格林尼治)时间,也叫世界时(Universal Time),也叫世界标准时间。是指位于英国伦敦郊区的【皇家格林尼治天文台】的标准时间,是本初子午线上的地方时,是0时区的区时。GMT格林威治时间可认为是以前的标准时间
UTC 全称Coodinated Universal Time 协调世界时,又称世界统一时间、世界标准时间、国际协调时间。它是以原子时(物质的原子内部发射的电磁振荡频率为基准的时间计量系统)作为计量单位的时间,计算结果极其严谨和精密。它比GMT时间更来得精准,误差值必须保持在0.9秒以内,倘若大于0.9秒就会通过闰秒来”解决”。UTC时间是现在使用的世界时间标准
DST Daylight Saving Time的简称,又称“日光节约时制”和“夏令时间”,也叫夏时制。表示为了节约能源,人为规定时间的意思。在这一制度实行期间所采用的统一时间称为“夏令时间”,在欧洲和北美用得比较多
PDT 全称Pacific Daylight Time太平洋夏季时间,也称夏令时。每年的3月份第二个星期日凌晨2点开始至11月份第一个星期日凌晨2点结束,第一天23个小时。「北美的西海岸太平洋沿岸地区,大城市有:温哥华,西雅图,旧金山,洛杉矶,拉斯×××,圣迭戈,萨克拉门托,波特兰等」
PST 全称Pacific Standard Time太平洋标准时间,也称冬令时。从11月份第一个星期日凌晨2点开始至次年3月份第二个星期日凌晨2点结束,第一天25个小时。
CST CST可视为中国、古巴的标准时间或美国、澳大利亚的中部时间CST可以表示如下4个不同的时区的缩写:中国标准时间:China Standard Time UT+8:00古巴标准时间:Cuba Standard Time UT-4:00美国中部时间:Central Standard Time (USA) UT-6:00澳大利亚中部时间:Central Standard Time (Australia) UT+9:30因此具体含义需要根据上下文环境确定具体含义。在中国就表示东八区”北京时间”
UTC+08:00 基于UTC标准时间的时区偏移量,可表示东八区。UTC±[hh]:[mm]形式表示某个时区的区时,由UTC和偏移量组成。UTC+08:00就表示东八区时区的本地时间 = 世界协调时间UTC + 时区偏移量(+8h)
ISO 在时间日期上它全称是ISO 8601,是一种日期/时间表示方法的规范。规定了一种明确的、国际上都能理解的日历和时钟格式。在Java语言中常见格式:●ISO.DATE:yyyy-MM-dd, e.g. “2023-02-03”●ISO.TIME:HH:mm:ss.SSSXXX, e.g. “10:30:00.000-11:00”●ISO.DATE_TIME:yyyy-MM-dd’T’HH:mm:ss.SSSXXX, e.g. “2022-10-31T01:30:00.000-05:00”.
时间戳 时间戳一般指的UNIX时间,或类UNIX系统(比如Linux、macOS等)使用的时间表示方式。定义为:从UTC时间的1970-1-1 0:0:0起到现在的总秒数(秒是毫秒、微妙、纳秒的总称),可简单理解为某个时刻

问题

一般MySQL Server 实例都会设置 time_zone 为 system,方便实例部署在不同的国家、时区也都能很好兼容,这是很合理的设置。

如果我们的 SQL 中有一个列类型是 timestamp 的话,意味着:

timestamp 数据类型会存储当时 session的时区信息,读取时会根据当前 session 的时区进行转换;而 datetime 数据类型插入的是什么值,再读取就是什么值,不受时区影响。也可以理解为已经存储的数据是不会变的,只是 timestamp 类型数据在读取时会根据时区转换

如果MySQL 读取 timestamp 字段时,需要做时区转换,当 time_zone 设置为 system 时,意味着MySQL 要去follow OS系统时区,也就是把读到的timestamp 根据OS系统时区进行转换,这个转换调用OS 的glibc 的时区函数来获取 Linux OS 的时区,在这个函数中会加 mutex 锁,当并发高时,会出现 mutex 竞争激烈,每次只有一个线程获得锁,释放锁时会唤醒所有等锁线程,但最终只有一个能获取,于是一下子导致系统 sys飙高、上下文切换飙高。每读取一行带 timestamp 字段时,都会通过这个 glibc 的时区函数导致锁竞争特别激烈最终 QPS 拉胯厉害。

想一想,你一个SQL查1万行,10个并发这点流量其实一点都不过分,但是这里需要10*1万次转换,锁争抢就激烈了。

分析参考这个: https://opensource.actionsky.com/20191112-mysql/

perf 以及火焰图如下:

image-20230830101924021

img

timezone

解决

在中国可以将 time_zone=’+8:00’ 将 time_zone 固定死,不再需要follow OS 时区,所以也不需要调用glibc 获取系统时区,避免了前面所说的锁竞争

这个经验来自无数次线上故障复盘,因为 time_zone 设置为 system 是个默认行为,所以要全部改过来还真不容易,给了我们就业机会 :)

当然学习总是希望交叉起来,既有深度又有宽度你才能掌握更好,所以请趁热打铁:

进一步学习

东八区CST 被JDBC 驱动错误识别成了美国的中央时间,官方修复: 8.0.23 改了 CST 解析行为(不再依赖 server 字符串),但完全规避时区坑还是要靠显式 serverTimezone=Asia/Shanghai 或服务端 time_zone=’+08:00’,不能光靠升驱动。

实验

在我们 99块钱的 ECS 启动一个MySQL 的Docker 容器(配置简单,换MySQL版本对比也方便)

1
docker run --name mysql --network host -v /plantegg/test/my.cnf:/etc/my.cnf   -e MYSQL_ROOT_PASSWORD=123 -d mysql --character-set-server=utf8mb4 --collation-server=utf8mb4_unicode_ci

my.cnf配置文件

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
43
44
45
46
47
# cat /plantegg/test/my.cnf
[mysqld]
#skip_grant_tables=1

#innodb
innodb_flush_log_at_trx_commit=0
innodb_buffer_pool_instances=8
innodb_max_dirty_pages_pct=60
innodb_io_capacity=6000
innodb_open_files=615350
innodb_buffer_pool_size = 64G

#binlog
binlog_cache_size=32K
max_binlog_cache_size=2147483648
max_binlog_size=1000M
sync_binlog=0

#for manager
#lower_case_table_names=1
#sql_mode = 'NO_ENGINE_SUBSTITUTION'

slow_query_log=0
general_log=0
default_authentication_plugin=mysql_native_password

max_connections=2000
max_user_connections=2000
max_connect_errors=65536
max_allowed_packet=1073741824
connect_timeout=8
net_read_timeout=30
net_write_timeout=60
back_log=1024

# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0

log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid
datadir=/var/lib/mysql
socket=/var/run/mysqld/mysqld.sock
secure-file-priv=/var/lib/mysql-files
#user=mysql

[client]
#socket=/var/run/mysqld/mysqld.sock

先创建一个Database ren,然后在里面再创建一个表t,如下:

1
2
3
4
5
6
CREATE DATABASE `ren` /*!40100 DEFAULT CHARACTER SET utf8mb4 COLLATE utf8mb4_unicode_ci */ /*!80016 DEFAULT ENCRYPTION='N' */

Create Table: CREATE TABLE `t` (
`ts` timestamp NULL DEFAULT NULL,
`dt` datetime DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci

插入一条数据:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
insert into t values('2021-12-02 16:45:39','2021-12-02 16:45:39');

//然后反复多次执行如下SQL,让数据条数不断翻倍,直到100万条左右
insert into t select * from t;

MySQL [ren]> select count(*) from t;
+----------+
| count(*) |
+----------+
| 1048576 |
+----------+
1 row in set (0.060 sec)

MySQL [ren]> show global variables like '%zone%';
+------------------+--------+
| Variable_name | Value |
+------------------+--------+
| system_time_zone | UTC |
| time_zone | SYSTEM | —————— 注意这里默认是System,
+------------------+--------+
2 rows in set (0.002 sec)

现在我们基本得到了一个100万行的测试表,接下来就要实验验证,同时开30个并发来查 ts列(timestamp, 要做时区转换) VS 查 dt 列(不需要做时区转换),对比他们的效率:

1
2
3
4
for i in {1..30}; do  (time mysql -h127.0.0.1 -P3306 -uroot -p123 ren -e " select ts from t " >>tmp ) & done

---上面30次 select每次基本需要20多秒,下面30次 select 每次基本需要4秒左右,性能差异有5倍
for i in {1..30}; do (time mysql -h127.0.0.1 -P3306 -uroot -p123 ren -e " select dt from t " >>tmp ) & done

可以清楚地看到 查ts 需要20秒左右,查 dt 需要4秒左右,差了5倍,结合我们前面的理论讲解,肯定可以想到这是在做时区转换有额外的开销,其实这还好只是开销大了几倍,有没有一种可能因为glibc 加锁导致整个系统雪崩了?大家可以试试能否搞出雪崩的场景来

Perf 安装和使用命令:

1
2
yum install perf -y
perf top -p mysqld-pid

比如用 perf top 可以看到查 timestamp 才有如下图前两行的 futex_wait_setup/libc-2.28 的wcscoll_l , 对比一下查 datetime 是完全看不到这些内核、libc的消耗的:

64 核机器 CPU 使用率(CPU 核数越多反而性能越差)

image-20241012175910202

image-20241012175910202

如果只给 MySQLD 4 核反而跑得更快了,明显在锁上的 CPU 消耗降低了很多:

image-20241012175910202

image-20241012175910202

停下来花点时间来分析他们的性能差异,多结合理论表述这篇,另外反过来想想如果你不知道这个原因,但是你看到这个现象(timestamp 和 datetime 性能差5倍的时候),你怎么来分析是为什么?

96核环境下对比

找个核数多的机器做同样的测试,比如以下数据是在96核机器上完成,让锁竞争更激烈,实际是把问题更加明显化

image-20240308084631703

从 top 也可以看到CPU 都花在了sys(内核态系统调用)上,这明显是不符合逻辑的。同时也可以看到96个核基本都跑满,整个MySQLD 进程的CPU 消耗接近 9600%,又回到了我们常说的CPU 有使用没有效率,不过站在CPU的角度是有效率的,这个效率都是在做锁相关的事情,但是站在业务角度是没有效率的:

image-20240308084600599

在这么明显的不正常情况下可以进一步通过 perf record 来采集调用关系,通过调用关系来回溯是哪个函数导致的锁争抢从而找到问题

从这里也可以看到这个问题在不同核数下表现完全不一样,如果只是一个核很少的实例那么看起来问题还没那么明显,只是慢了,但是到了96核下这个SQL 反而全崩了,这个SQL 完全查不出结果(CPU 都在sy 上干抢锁的内耗上,能查出才怪),核数越多这个问题就越严重,也即内耗越严重,如果有业务流量源源不断地进来就类似雪崩了:

1
2
3
4
5
6
7
8
9
# mysql -h127.0.0.1 -P3306 -uroot -p123 ren -e "show processlist"
+------+-----------------+-----------------+------+---------+---------+------------------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+------+-----------------+-----------------+------+---------+---------+------------------------+------------------+
| 1195 | root | localhost:46528 | ren | Query | 556 | executing | select ts from t |
| 1196 | root | localhost:46530 | ren | Query | 556 | Sending to client | select ts from t |
| 1197 | root | localhost:46532 | ren | Query | 556 | executing | select ts from t |
| 1198 | root | localhost:46538 | ren | Query | 556 | executing | select ts from t |
| 1199 | root | localhost:46540 | ren | Query | 556 | executing | select ts from t |

代码分析

从下图可以看到 70% 的 CPU 时间消耗在 Time_zone_system::gmt_sec_to_TIME() 方法的调用上,就是以下这一段的代码。

timezone

对应代码:

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
43
44
45
46
47
48
49
50
51
52
53
54
55
void Time_zone_system::gmt_sec_to_TIME(MYSQL_TIME *tmp, my_time_t t) const {
struct tm tmp_tm;
time_t tmp_t = (time_t)t;
localtime_r(&tmp_t, &tmp_tm);
localtime_to_TIME(tmp, &tmp_tm);
tmp->time_type = MYSQL_TIMESTAMP_DATETIME;
adjust_leap_second(tmp);
}

//继续下钻来看一下 __tz_convert() 的实现,代码如下
/* Return the `struct tm' representation of *TIMER in the local timezone.
Use local time if USE_LOCALTIME is nonzero, UTC otherwise. */
struct tm *
__tz_convert (const time_t *timer, int use_localtime, struct tm *tp)
{
long int leap_correction;
int leap_extra_secs;
if (timer == NULL)
{
__set_errno (EINVAL);
return NULL;
}
__libc_lock_lock (tzset_lock);
/* Update internal database according to current TZ setting.
POSIX.1 8.3.7.2 says that localtime_r is not required to set tzname.
This is a good idea since this allows at least a bit more parallelism. */
tzset_internal (tp == &_tmbuf && use_localtime, 1);
if (__use_tzfile)
__tzfile_compute (*timer, use_localtime, &leap_correction,
&leap_extra_secs, tp);
else
{
if (! __offtime (timer, 0, tp))
tp = NULL;
else
__tz_compute (*timer, tp, use_localtime);
leap_correction = 0L;
leap_extra_secs = 0;
}
if (tp)
{
if (! use_localtime)
{
tp->tm_isdst = 0;
tp->tm_zone = "GMT";
tp->tm_gmtoff = 0L;
}
if (__offtime (timer, tp->tm_gmtoff - leap_correction, tp))
tp->tm_sec += leap_extra_secs;
else
tp = NULL;
}
__libc_lock_unlock (tzset_lock);
return tp;
}

代码最终会使用 atomic_compare_and_exchange_val_24_acq() 尝试对 futex 加锁。

futex 作为多个 thread 间共享的一块内存区域在多个 client thread(多个会话/查询)竞争的场景下会引发系统调用而进入系统态,导致 SYS 系统态 CPU 使用率上升。

并且该临界区保护的锁机制限制了时区转换方法 __tz_convert() 的并发度,进而出现多个会话/查询 等待获取锁进入临界区的情况,当冲突争抢激烈的场景下引发卡顿

进一步验证

这几个算是你可以接着做的一些小任务

  • 将 time_zone 从system 改成 ‘+08:00’ 再查 timestamp 列看看是不是就不存在这个问题了,反复改来改去稳定确认
  • 换MySQL 5.6/5.7试试这个问题,默认用的MySQL 8.0
  • 换低版本的OS 内核试试这个问题,我测试用的5.10,你可以试试3.10
  • 构造雪崩,也就是随着并发、行数的加大系统陷入抢锁等锁,基本无法响应业务查询了
  • 在这个基础上,各种折腾、折腾,会折腾就是能力

总结

借着 MySQL 的时区转换我们把这个问题重现了,让我们通过实际测试来验证这个差异,下次我相信你会对这个问题印象深刻的

当然我们做这个实验不是为了证明这个问题,这个知识点本身价值不是特别大,而是希望你能学到:

  1. 设计实验,根据你的目的设计实验
  2. 根据实验重现的现象反过去分析为什么——虽然你知道原因,但是如果不知道你会怎么思考
  3. 尝试分析问题的手段、技巧,比如 perf、比如for 循环

希望能看到你们更多的不同实验现象和分析

localhost和127.0.0.1的区别

背景

有人告诉我localhost和127.0.0.1的区别是localhost 不经过网卡,所以性能也高。把我惊到了,因为我还真不知道这个知识点,于是去特别去验证了一下:这是个错误的理解。正确的解释是:localhost会解析成127.0.0.1 然后接下来的流程和127.0.0.1 一模一样

我用Google搜了下标题,果然得到如下图:

image-20230910100147730

红框里是排第一、第四的文章,都大言不惭地说localhost不经过网卡、不受防火墙限制等。

我也看了下第二、第三的文章,这两篇都是说在MySQL命令行中连 localhost 的时候,MySQL命令行会判断 localhost 这个字符串认为是本地连接然后不走DNS 解析流程(走的话就肯定解析成了127.0.0.1),从而绕过OS 的内核网络协议栈用MySQLD 启动的时候生成的 unix-socket 管道直接连上MySQLD,这样效率更高。

错误信息大概就是在MySQL这个特殊场景下演变而来的,英文搜索就没有这个错误污染信息

但这不是我要说的重点,我想说的是自己动手去求证!这一直都是我们星球里强调的能力和目标,我把这条发到Twitter上后有无数的初学者跑出来质疑或者一知半解不去验证就丢一个结论,这是我比较痛恨的。比如:

  • Localhost 写死了在 /etc/hosts(那我就要问,你清空/etc/hosts localhost还能工作吗?)

  • Localhost 不走网卡(但凡抓个包就知道走了,我估计他们抓了,抓的是eth0. 这里有个小小的歧义 loopback 本地回环网卡算不算网卡)

所以我特意再写篇文章再验证下各种质疑,并让大家看看是怎么验证的,我希望你们可以跟着验证一遍而不是只要知道个结论

结论

Localhost 会按dns解析流程进行解析,然后和127.0.0.1 一样。在特殊的程序中比如 MySQL client 会对localhost提前做特别处理。

完整的区别见这篇英文(Google 英文第一篇就是)总结:

image-20230910101843256

验证

问题1:经过网卡吗?

Ping localhost/127.0.0.1,然后 tcpdump -i any icmp or icmp6 [说明:any(抓所有网卡)icmp (精确点只抓ping包) ],可以明显抓到网络包,所以你可以理解为经过网卡。这指的是这个网络包完整地经过了内核协议栈,加tcp包头、ip包头、mac 包头等等。

而很多人理解的不经过网卡是指不走内核协议栈(毕竟是本机),加tcp包头、ip包头、mac 包头然后又脱mac包头、脱ip包头、tcp包头,有点像没必要的折腾。比如你通过unix socket 连就不走内核协议栈,性能要高一些

严格来说是没经过物理意义上的网卡,因为 lo 是一块虚拟网卡,不需要插网线,不会真的走到网卡、网线然后回来。如果让内核重新设计,让127.0.0.1 不过经过内核协议栈行不行?我觉得是完全可以的,当时为什么这么设计我也不懂。

总之,我强调经过网卡是从完整经过了内核协议栈、用 tcpdump 能抓到这个概念上来说的,为了跟别人说用127.0.0.1比用本机物理IP 性能要好而言(实际没有区别),你如果用本机物理IP 也同样走 lo 网卡

问题2:localhost和127.0.0.1 的关系

如图是我在centos、微软azure(应该是个ubuntu)、macOS下做的测试:

image-20230910103644707

问题3:如果/etc/hosts 中没有写死 localhost 127.0.0.1 会怎么样?

如下图,ping的时候即使没有 /etc/hosts 也可以把localhost 解析成127.0.0.1,为什么呢?所以接着我就 nslookup 看一下是哪个 DNS server做的这事,最后我用114.114.114.114 这个公网的DNS 做了解析,就不认识localhost了,说明去掉 /etc/hosts 之后 会把localhost 发给dns server解析,标准的dns(比如114.114.114.114,8.8.8.8) 都不会返回127.0.0.1 ,但是有些特定的实现为了省事帮你解析到127.0.0.1了

image-20230910104133832

问题4:127.0.0.1比localhost少了查/etc/hsots 到底快多少?

这个问题来自这个评论:https://twitter.com/InnerHack/status/1700012845302436087 所以我去验证了一下,特别强调这个数据意义不大,但是你们可以学会用strace,命令:

1
strace -tt ping -c 1 localhost

然后你得到如下图,从strace时间戳你可以看到 localhost 解析成127.0.0.1 的过程,再后面就是ping 127.0.0.1(这里也说明了前面的结论,两者是一样的,就是多了域名解析)

image-20230910104733229

域名解析的时候,先去找/etc/hosts 没找到再去找 /etc/resolv.conf 拿dns server ip然后把localhost发给这个dns server 解析,tcpdump抓包如下,红框是dns server返回的结果:

image-20230910105107629

问题5:127.0.0.1 和127.1 的关系

127.1 会自动补全成127.0.0.1

问题6:为什么还是抓不到包

ping localhost的时候没有包,只有127.1有,如下图:

image-20240505103504490

这是对提示信息敏感度不够,仔细看上图右下角的 ::1 这是个ipv6地址;也就是localhost被默认指向了这个 ipv6(localhost其实可以随便配置指向哪里,新一点的OS 默认都是指向 ipv6了),抓包命令多加一个 icmp6 (一个协议名字,默认不抓这个协议) 就能抓到了:tcpdump -i any icmp6

总结

唯有动手能解释一切,不要空逼逼(不是说你们,是说Twitter上那帮人,我是被他们留言多了逼着写了这篇)

我是欢迎一切有理有据的质疑,事实文中很多信息来源于别人的质疑,然后我去验证

然后好多验证手段你们可以学学,比如nslookup/tcpdump/strace 等。

我给的文章链接也可以仔细读读,能学到很多东西,每一次进步都来自你深挖、展开能力。

RFC6761 中对 localhost 有详细的说明,且已经定义的非常清楚:localhost 表示Loopback Address(127.0.0.1 或 ::1),另外应用程序可以对这个域做特殊识别处理,可以不走DNS解析流程。

解决 Java/MySQL 性能问题的思路

10年前写的,重新发一下

系统性能问题

  • CPU(基本上WEB服务器没有多少IO,主要是CPU有瓶颈)
    • top/vmstat 观察CPU使用率,Load负载,r/b线程数量等;
    • IO(数据库大多数时候瓶颈是IO,主要是索引没建好;如果数据库CPU紧张的话,检查一下是不是order by/group by 等操作太多)
    • vmstat 观察IO/Util吞吐,磁盘最怕随机读写了(比如:索引命中后,需要离散地从磁盘读数据)
    • 对于数据库来说最怕内存不够的时候使用Swap了,所以尽量增大分配给数据库的内存,一旦有Swap就要引起注意了

Java程序问题(运行慢)

​ 先通过 top 查看整个CPU资源使用情况;
​ 通过top -Hp pid查看java进程的每一个线程占用CPU的情况;
​ 如果有一个线程占用CPU过高,有两种可能:
​ 没有内存了,Java垃圾回收线程不停地运行尝试回收内存,但是每次无法收回,确认:
​ jstat -gcutil pid 1s 观察10多秒钟就能发现了,看是不是内存使用率接近100%了
​ 类似于死循环(hash冲突攻击),就是一个线程一直占用一个核的所有CPU资源(其实一个线程总是占用一个核超过50%的资源都是不太正常的),解决:
​ 用我的checkPerf脚本,定位这个线程具体执行的任务(能具体到某一行),对应看代码解决。

    如果有很多线程,每个线程占用的CPU都不多(基本都在10%以下),那基本是正常的,只是程序并发确实很高。

如果死锁:
    jstack -l pid 多执行几次,统计一下stack中总是在等待哪些锁,可以对锁id进行排序统计(sort uniq grep)
上面列出来的都是明显的瓶颈,最可怕的是哪里都没有明显的瓶颈,哪里都要偷一点点CPU资源走,这是可以试试JProfiler这样更专业一点的工具,同时要配合自己对业务的了解来解决。

一旦触发频繁地抛出异常,CPU占用率会急剧地上升(抛异常比正常情况下会慢2个数量级)主要是由于:Throwable的构造函数中会调用native的fillInStackTrace(),这个方法就会构造整个异常栈了。

Java内存的问题,如果有内存泄露(就是执行完fgc/old gc后不能回收的内存不断地增加):
怎么确认没有内存了:
jps -lmv pid 先确认你的参数,也就是你给JVM分配了多大的堆(-Xmx 比如1G); 然后jstat -gcutil pid 1s 看看GC运行情况,如果(O/E 两列基本接近100%的话就是内存不够了)
内存不够分两种:一种是真的不够,就是你们的系统很庞大需要1G以上的内存,而你只分配了1G,这个没什么好说的,增大内存,物理内存不够就投钱买;
第二一种是你们的代码写的烂,有内存泄露,这样的话分配多少内存都不够,得找出是否有内存泄露,看接下的解决方案

快速解决:jmap -histo:live pid  来统计所有对象的个数(String/char/Integer/HashEntry 这样的对象很多很正常,主要是盯着你们公司的包名下的那些对象)
每隔一分钟执行一次上面的命令,执行5次以上,看看你们公司报名下的对象数量哪个在一直增加,那基本上就是这个对象引起了泄露;
用课堂上的工具HouseMD(java -Xbootclasspath/a:/usr/java/jdk1.6.0_29/lib/tools.jar -jar housemd-assembly-0.2.2.jar pid)来动态监控创建这个对象的地方(一般来说很多时候创建了这些对象把他们丢到一个HashMap然后就不管了),分析一下有没有释放!
    >trace -s -d ClassName

上面的方法实在没法定位就用: jmap -dump:live,format=b,file=heap.bin pid 导出整个内存(耗时间,需要很大的内存的机器才能对这个导出文件进行分析,会将JVM锁住一段时间)
    在Eclipse的插件EMA中打开这个文件(2G的物理文件需要4G以上的内存,5G以上的需要将近20G的内存来分析了)
    盯着你们公司报名的那些对象,看看引用关系,谁拿着这些对象没释放(是否是必要的),可以一直追查的RootReference

MySQL 数据库的性能问题

大部分情况下是磁盘IO的问题(索引没建好、查询太复杂);

  • 索引问题的话分析慢查询日志,explain 他们挨个解决。

  • 偶尔也有数据库CPU不够的情况,如果并发高CPU不够很正常,如果并发不高,那很可能就是group by/order by/random之类的操作严重消耗了数据库的CPU

    1
    2
    3
    mysql -e "show full processlist" | grep -v Sleep | sort -rnk6 查看那些SQL语句执行的太长
    拿出这个SQL语句分析他们的执行计划: explain SQL 然后改进;
    分析慢查询日志,统计top10性能杀手的语句,挨个explain他们,然后改进(具体改进办法具体分析,这里只谈思路)

总结一下数据库问题就只有这三招:show full processlist/分析慢查询日志/explain(然后建好联合索引)

补充一个数据库连接数不够的问题,很多人碰到了,不知道怎么解决:

  • 在mysql 命令行里执行:show variables like ‘%max_connections%’; 看看你们的数据实际配置是多少(比如1000)
  • show full processlist 数一下多少行,一行代表一个连接,比如这里是1000行,那基本上就是连接数不够了,你要解决的为什么你的数据库需要这么多连接
  • 接下来分析这些连接是从哪来的IP,然后问你自己:根据你们的服务类型的特点需要这么多连接吗?

数据库性能问题提问请给出:

  • show full processlist;
  • 查询语句;
  • 表结构(包括索引结构);
  • 数据库引擎类型;

如何从几百万个抓包中找到一个异常的包

这篇算是对抓包定位原因在哪里的落地篇,没什么高深的技术,都是很low但是你一定可以照着操作的,算是星球内必须学会和带走的内容

场景

image-20230620150119963

问题

一次业务请求包含160个拖数据的SQL查询,通过160个连接,发给160个Database,但是过几分钟后总有报错。几分钟抓包文件10G左右,网络包几百万个,怎么找到报错的那个?

几个麻烦的地方

  • 虽然问题每次稳定重现,但是每次重现的Database不是固定的;
  • 从开始拖到出现问题需要几分钟不等,抓包量巨大
  • 有一个连接报错后剩下的其它连接也会断开
  • 这么多端口怎么解析成MySQL协议,请看:https://t.zsxq.com/0f7nMlKax

问题发生条件

  • 一个Client同时开160条连接,发160个类似的SQL去160个MySQL Database上拖数据时必现
  • 如果将拖数据的SQL拖取数量改小一点就不再出现——拖取少执行更快,没达到触发bug条件
  • 网络传输得慢一点、JDBC streaming 模式下发生,比如streaming流模式拖数据是几MB每秒,去掉流模式拖数据是几十MB每秒且不报错。这里可以通过设置内核 tcp rmem/加大rtt延时来模拟重现——和我们的必做实验callback一下,无时不刻不展示下我们必做实验的用途。

分析过程

分析技巧和步骤:

  1. 抓包,从握手到报错断开全抓下来,时间跨度3分多钟,抓下来10个G左右,怎么分析?
  2. editcap -c 200000 把抓包切小,每个文件20万个包,保证wireshark打开不太慢(editcap 是安装wireshark附带的小命令,附带的还有tshark、capinfos等)
  3. wireshark打开切小后的最后一个文件,搜reset/fin 找到第一个断开的连接(如下图),找到9913/42909这对连接端口
  4. 回到10个G的抓包中,用 tshark -r ./big.pcap -Y “tcp.port==42909” -w 42909.pcap 把42909这条连接所有包过滤出来,-r 读,-w 写
  5. wireshark 打开42909.pcap 傻子也能看到问题在哪里了

切完后的包,切完后的文件会加时间戳,时间戳可以和报错时间对应:

1
2
3
4
5
6
7
8
9
-rw-r--r--  1 root  root   329M Jun 16 17:46 big00_00000_20230616170456.pcap
-rw-r--r-- 1 root root 1.1G Jun 16 17:46 big00_00001_20230616170524.pcap
-rw-r--r-- 1 root root 1022M Jun 16 17:46 big00_00002_20230616170546.pcap
-rw-r--r-- 1 root root 1.1G Jun 16 17:46 big00_00003_20230616170608.pcap
-rw-r--r-- 1 root root 1012M Jun 16 17:46 big00_00004_20230616170630.pcap
-rw-r--r-- 1 root root 982M Jun 16 17:46 big00_00005_20230616170652.pcap
-rw-r--r-- 1 root root 938M Jun 16 17:46 big00_00006_20230616170714.pcap
-rw-r--r-- 1 root root 1.1G Jun 16 17:46 big00_00007_20230616170735.pcap
-rw-r--r-- 1 root root 661M Jun 16 17:46 big00_00008_20230616170759.pcap

搜reset/fin 找到第一个断开的连接,第一个断开的连接才是罪魁祸首:

image-20230620143248344

进一步分析发生问题的连接

知识点:

MySQL 协议是一来一回,也就是client发查询然后等查询结果全部返回,然后再发下一个

按协议在一个SQL查询的数据传输完毕前client不能再发任何请求,MySQL Server负责一直发送查询结果直到发送完毕。

如下两个截图是从42909.pcap文件中过滤到的抓包从握手到断开的全过程,图1过滤条件:tcp.srcport eq 42909 and tcp.len>0 (42909是客户端,9913是MySQL端口),可以看到客户端 login(连数据库肯定得要user、password认证),然后是client查了MySQL的一堆服务端参数(下图第二行),再然后是client设置了几个参数(set 那些)。关键的是倒数第二行client发了一个SQL给MySQL需要拉取大量数据(建立连接17.98秒的时候),然后是数据传数据过程,第190秒的时候client发了 Quit断开连接

image-20230620140921134

上图因为加了过滤条件,只看client端并去掉ack后的所有包,没看到全貌,这个过程9913的MySQL 服务端又做了啥呢?因为太长前面漫长的传数据就不截图了,只看最后连接的断开。

但是下图红框所示的地方可以看到MySQL Server 传着传着居然带了个 fin 包在里面,表示MySQL Server要断开连接了,无奈Client只能也发送quit 断开连接。红框告诉我们一个无比有力的证据MySQL Server 在不应该断开的地方断开了连接,问题在 MySQL Server 端

image-20230620141017987

结论

就抓包结论来看是 MySQL 在不应该断开的时候发送了 fin 主动断开连接,可能是MySQL的bug

题外话,这个包证据抓了有一周了,但是MySQL研发同学始终绕来绕去(比如我的代码没记录下这个SQL就是没收到,我的代码没问题——熟悉的味道)跟我打了一周太极(异地),我一查发现我和他老板认识且在一层楼,赶紧面对面找他老板讲清楚这个问题,且签字画押承认是MySQL的问题,然后继续推进排查,最终结果是为啥我跟你们一起期待吧,有了结果我再来update。

练习

找个MySQL,然后开始抓包,用mysql-client连一下MySQL Server随便发几个SQL,然后看看一来一回的响应

如果哪怕在星球一年你只要好好掌握这一篇用到的技能也能帮助你在日常工作中互相扯皮的时候快速给出精准定位和分析,值回星球票价,加油

比如这个案例我同时打开了5/6个wireshark分析不同的流、整体搜索等

其它

这些技巧不只是用在MySQL 上,其它微服务、redis等涉及网络调用场景的扯皮的地方都可以用

wireshark 附带的一些小工具

capinfos rsb2.cap

tshark -q -n -r rsb2.cap -z “conv,ip” 分析流量总况

tshark -q -n -r rsb2.cap -z “conv,tcp” 分析每一个连接的流量、rtt、响应时间、丢包率、重传率等等

editcap -c 100000 ./rsb2.cap rsb00.cap //把大文件rsb2.cap按每个文件100000个package切成小文件

存放在这里:

1
2
3
4
5
6
7
8
9
10
/usr/sbin/capinfos
/usr/sbin/dftest
/usr/sbin/dumpcap
/usr/sbin/editcap
/usr/sbin/mergecap
/usr/sbin/randpkt
/usr/sbin/rawshark
/usr/sbin/reordercap
/usr/sbin/text2pcap
/usr/sbin/tshark

net_write_timeout 报错

最后回答一下上一篇中提到的流模式下 net_write_timeout 报错

如下图,JDBC 在 streaming 模式下,不断读取下一行,如果这个过程只要报错抛出的异常就是 StreamingNotifiable 异常

image-20230620173111706

错误信息定义如下,这个报错误导太严重,从以上JDBC 代码可以看到只要读取下一行报错了就会报调大 net_write_timeout 错误,但是实际原因却是连接异常断开,和 timeout 没有一点关系,你看久经考验的 JDBC 代码也不是那么完善还得你会 Debug

1
CommunicationsException.ClientWasStreaming=Application was streaming results when the connection failed. Consider raising value of ''net_write_timeout'' on the server.

这个报错误导了排查分析方向,不知道坑了多少人了!当然如果MySQL 因为net_write_timeout 超时断开连接当然应该报如上错误,但是 JDBC 搞不清楚MySQL 为啥断开,就瞎猜是 timeout 了,然后只要是连接异常读数据错误(包含断开)就报这个错误。希望你们不要被坑

记住这个坑人的报错堆栈:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Application was streaming results when the connection failed. Consider raising value of 'net_write_timeout' on the server.
at sun.reflect.GeneratedConstructorAccessor150.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:989)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3749)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3649)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4090)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:972)
at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:2123)
at com.mysql.jdbc.RowDataDynamic.nextRecord(RowDataDynamic.java:374)
at com.mysql.jdbc.RowDataDynamic.next(RowDataDynamic.java:354)
at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:155)
at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:6726)
at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:865)
at com.alibaba.druid.pool.DruidPooledResultSet.close(DruidPooledResultSet.java:86)

不过你要仔细看的话,它还是有caused by,如下,但是绝大部分工程师看到这个堆栈会忽视,上面都有 net_write_timeout 我还管个屁 Can not read response from server, 不过要是结合抓包的话就能理解:at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3186) 这个根本的原因是 JDBC 从服务端读取数据的时候报错了

1
2
3
4
Caused by: java.io.EOFException: Can not read response from server. Expected to read 405 bytes, read 272 bytes before connection was unexpectedly lost.
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3186)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3709)
... 40 common frames omitted

最后希望你没被绕晕,再去看看上一篇中推荐的流模式原理,把代码和网络应用层完美地结合起来

完整堆栈也可以参考网络上别人碰到的:https://github.com/brettwooldridge/HikariCP/issues/1771

看 Google 里面对这个问题的分析基本都没入门:https://www.google.com/search?q=Caused+by%3A+com.mysql.jdbc.exceptions.jdbc4.CommunicationsException%3A+Application+was+streaming+results+when+the+connection+failed.+Consider+raising+value+of+%27net_write_timeout%27+on+the+server.&hl=en&sxsrf=APwXEddTwJGjFpkKuWHyXjlTvwTo2OUMhA%3A1687226872136&ei=-AmRZI7gB6-C0PEPmOGbwAE&ved=0ahUKEwiOvPny4dD_AhUvATQIHZjwBhgQ4dUDCBE&uact=5&oq=Caused+by%3A+com.mysql.jdbc.exceptions.jdbc4.CommunicationsException%3A+Application+was+streaming+results+when+the+connection+failed.+Consider+raising+value+of+%27net_write_timeout%27+on+the+server.&gs_lcp=Cgxnd3Mtd2l6LXNlcnAQA0oECEEYAFAAWABgAGgAcAF4AIABAIgBAJIBAJgBAKABAqABAQ&sclient=gws-wiz-serp

下次在你们的业务代码里如果出现查询结果太大导致JVM OOM的话你可以站出来说把拉取数据改成 流 模式会有奇效 :) , 当然随之而来的是会有 net_write_timeout 报错,嗯,你的机会来了,业务技术上按照你的指引发展,出了问题你能顶得上

扑朔迷离的根因分析–抖动和并发

前言

我们之前说过根因分析第一就是要追着 RT跑,随着并发的增加哪里RT增加快哪里就是瓶颈,这是我们的基本原则,但总有一些例外,我们今天想说说例外

场景

如下图,应用是多个Tomcat集群,Tomcat节点可以随意增加,后端是一组DB集群,有几百个Database实例,每一次业务请求都会对应多个Database查询

image-20230609204957690

问题

开始的时候客户端压2个Tomcat集群,QPS 700,Tomcat节点CPU 90%,Database每个节点CPU 20%左右,于是增加1个Tomcat 节点这个时候QPS 还是700,Tomcat的RT增加了50%,Tomcat CPU 降低到60%,继续增加Tomcat 节点 RT、QPS保持稳定,CPU使用率下降。

所以这里要搞清楚哪里是瓶颈,如果Tomcat是瓶颈加Tomcat节点为什么没有效果。如果Database是瓶颈但是增加Tomcat节点的时候Database 的RT有一点点增加,远远没有到增加50%的RT 程度

分析

首先最容易想到的是Tomcat 和 Database之间的网络、网关、LVS 等资源到了瓶颈,但是经过排查分析这些环节都排除了,另外也排除了Tomcat到Database的连接池、Database的磁盘等瓶颈,另外Tomcat 访问Database全是查询,没有事务。

image.png

看起来事情比想象的复杂,于是进行了如下压测:

先用一个压力端压3个Tomcat中的2个,QPS 跑到700,然后新开一个压力端压第三个Tomcat(新开压力端是排查压力机的问题,新开Tomcat是想排除Tomcat 的问题),如果Tomcat是瓶颈的话QPS应该上去,或者说后端没有问题的话那两个Tomcat 的700 QPS得保持基本稳定不变或略微下降才对。

实际上第二个压力端跑起来后,前两个Tomcat的QPS 铛就掉下去了,总QPS 保持稳定不变,也就是随着Tomcat给后端并发压力的增加后端肯定给了一个负反馈给那两Tomcat,导致那两Tomcat QPS掉下去了。这个负反馈明显得是Database的RT在增加,但是从监控来看Database的RT 从0.6增加到了0.8,但是Tomcat 的RT 增加更快从19.7增加到了29.8.

单独压DB,DB的QPS能高5倍,CPU 也可以跑到100%。看起来单压都没问题,一组合就不行了

问题在Database

绕过Tomcat 用相同的SQL 压Database QPS 一下子就能上去,Database 的CPU 也跑到了100%,但是只要走Tomcat 就会上不去。

打开Tomcat 日志将所有Database的响应时间拉出来分析,发现随着并发的增加 100 ms的响应也多了很多,实际上这些查询都是1ms就应该返回

具体分析过程看这里:https://plantegg.github.io/2019/12/16/Intel%20PAUSE%E6%8C%87%E4%BB%A4%E5%8F%98%E5%8C%96%E6%98%AF%E5%A6%82%E4%BD%95%E5%BD%B1%E5%93%8D%E8%87%AA%E6%97%8B%E9%94%81%E4%BB%A5%E5%8F%8AMySQL%E7%9A%84%E6%80%A7%E8%83%BD%E7%9A%84/

原因

当压力增加的时候MySQL端等锁导致的 RT 抖动或者说长尾越来越多,虽然没有数据库的写,但是查询的时候优化器也需要统计行数等数据来为查询优化器做选择依据,这个统计动作会触发加锁排队(极短),但是因为这一代Intel CPU指令的变化导致这个锁被放大了10 被,所以最终Tomcat 端看到的长尾就多了

为什么

为什么同样的环境、同样的SQL 绕过Tomcat 就能压上去?

绕过后的压测场景没有业务逻辑,每次请求就是一条SQL,虽然有抖动但是对平均RT拉升不明显。

走业务逻辑压Tomcat 为什么不行?

业务逻辑是一次请求会发256条SQL,等这256条SQL全部返回来了业务请求才会返回!请反复读这句话3遍再往下看

如果256条SQL 中有一条花了100 ms返回那么整个业务逻辑的RT 就是100ms,假设1%的概率一条SQL是100ms,99%的SQL 是 1ms,你可以先停下来算一算这种业务模型下的平均RT是多少

计算抖动下的平均RT

关于这个抖动对整体rt的影响计算:

img

注:假设正常查询rt 1ms,逻辑平均rt=(1-power(1-抖动概率,物理查询次数))*抖动大小+(power(1-抖动概率,物理查询次数))*1ms

当前场景下,逻辑QPS:物理QPS=1:256,假如每次查询有1%的物理(RDS)rt抖动到100ms,则会导致逻辑平均rt恶化到92.44ms.

在一次逻辑查询里,只有所有物理查询都不抖整体才是不抖,RT正常;如果有一个或多个物理查询抖了,那么逻辑RT就是抖动RT。

所以一次逻辑查询不抖的概率是: power(1-抖动概率, 物理查询次数)

反过来想这256条SQL都不碰上抖动这次业务请求才会1ms返回(概率极低),否则就是256ms返回

为什么要讲这个案例

倒不是出于原因分析,这个原因几年前就分析清楚了,但是这个场景:一次业务请求会涉及多次SQL、Redis、MQ的调用,只要其中有一个有短板、抖动这次业务请求就慢了。这简直太常见了

但难在别人的抖动很低被平均掉了,但是业务(Tomcat) 就要替别人背锅了,因为别人的RT 几乎没有增加或者加很少,但是Tomcat RT增加很明显,瓶颈当然看着像是在Tomcat 上。背锅吧也不可怕可怕的是你增加Tomcat 节点也不能解决问题,这才是你要从这个案例里学到的。

如果你的Tomcat 调后端因为短板(抖动)导致压力打不到后端,因为抖动导致Tomcat不能快速返回

上游影响下游:

和本文无关但是可以放一起综合来看上下游互相影响的复杂性

以前认为事务不提交的主要代价是行锁持有时间变长(这确实是个问题),今天见识到了新代价,事务不提交会导致事务活跃链表变长,增加copy readview的代价,进而导致DB的RT 增高,实际导致DB RT高的根本原因是DB前面的业务早到了瓶颈,来不及发送commit,导致DB端事务堆积严重。也就是业务瓶颈导致了后端DB RT高,只看RT就会被蒙蔽——怎么解决?可以抓包看commit发送慢

扑朔迷离的根因分析

原则

追着RT 跑,不断加压力,到瓶颈前随着并发的增加RT很稳定。

但是你要对你的RT怎么来的,包含哪些环节的消耗,这样才不会出错。

如下图左边是QPS不停地增加,每一次台阶(增加20%流量)都是一次加压过程,右边是对应的 RT,可以看到在绿线阶段几乎是平稳的,直到最后的红色箭头 RT略微有一点点提升,但是整体也还好,说明基本没到瓶颈

image-20230520101758175

当然这个图是经过长时间调优的结果,来之不易,是理想的期望系统状态,但在这之前是长时间的痛苦分析和瓶颈在哪里的定位过程。

凡是复杂的实际业务总是有很多干扰项出现在你的理论图上,你得很好地识别他们

业务结构

image-20230517113148916

概念说明:

黑色=Database=被依赖业务=物理

蓝色=Tomcat=上游业务=逻辑

上游响应时间=下游业务响应时间+网络时间+上游自身处理耗时

响应时间=RT=耗时监控

tcprt:从内核网络取Database的响应时间

实际很魔幻的是同样流量有时候压测很稳定,有时候又不稳定,性能上不去(稳定时可能是压测数据、没有触发Database雪崩之类的问题),所以导致问题

所有压测过程中肯定是没有任何资源上的瓶颈(CPU、内存、网络带宽、磁盘等等)

监控数据

如图,蓝线表示Tomcat,黑线表示Database被调用方,可以看到每次黑色 RT上升QPS下跌很猛(符合预期),奇怪的是黑色RT很快降下来后蓝色RT还会维持较高一段时间,监控频率每5秒采集一次,以下所有监控图时间范围是一样的,但采集频率不一样

image-20230516150350614

(图1)

上图的两个 RT 监控数据都是Tomcat的业务代码记录下来的,比如Database的响应时间就包含网络+Database的处理时间

如下图通过网络监控看响应时间(tcprt 阿里云文档,从OS 内核中取到网络包的响应时间),蓝线表示Tomcat,紫线表示Database,监控力度每1分钟采集一次,有被平均

image-20230516150812485

以上两个监控图的矛盾点:如果从网络层面记录的Database RT 可以看到上升幅度不明显,但是Tomcat 的RT上升很明显,但是Tomcat记录的RT则又是Database 上升明显。

补充知识

tcprt和tomcat业务进程记录的 Database rt差异,tcprt记录到的是RDS/Database的响应时间+网络时间,tomcat在这个基础上还要加入自己进程调出处理时间,比如tomcat进程取到数据库连接的时候连接需要排队等待1秒钟(后面有分析),那么这个一秒钟对tcprt来说是不会记录进去的,但是客户端感知到的这次调用是1秒以上。当然业务记录的Database 还可以更精准,比如在连接池Druid(或者其它连接池的实现)内取记录,但是无论如何从业务进程到OS内核这里的差距总是存在的。

image.png

Tomcat CPU 监控

image-20230516150950383

问题

可以很清楚看到 QPS 下降是因为 RT上升,那么究竟是Database的RT上升导致的还是Tomcat的RT上升导致的。

但是我们从监控图也能看到Database RT降下来后Tomcat RT还维持高水位,所以有点迷惑了。

继续看另外案例

案例2 yy

两次压测监控数据,左右两个图标是同一时间的QPS和RT,蓝线表示Tomcat,黑线表示Database被调用方

image-20230519170255718

image-20230519172225890

从两个图来看,随着并发加高(QPS加高) 黑色RT增加明显,但是跑着跑着降下去了,可以理解成突发流量导致黑色RT增加,但是很快黑色RT稳住了阵脚,降回去了,但是蓝色 RT没降,所以表面看起来是蓝色(Tomcat)处理能力到了瓶颈

上图时间点内核监控的tcprt,可以看到还是Database 处理耗时增加,和上图的黑色RT下降根本不匹配,上图黑色RT最后在2.96ms,下图内核监控到的Database的tcprt在8.49,差异矛盾点

image-20230519172519802

第三次压测图

image-20230519165825977

从第一个图来看,随着并发加高(QPS加高) 黑色RT增加明显,蓝色 RT去掉黑色部分也有增加,并且黑色、蓝色都没降回去,看起来主要是黑色(Database)处理能力到了瓶颈

纠结的时候就在Tomcat上抓包确认一下,如下图黑色 Database服务端口是5493,可以看到Tomcat 发request总是很快,但是Database 响应都是几十毫秒(下图红色框),和监控一致。其实监控可以说明问题,但是我担心业务记录时间不准,以及建连接时间都考虑在内,所以想抓包微观上印证一下,这种项目牵扯到很多人你搞错了方向丢人不说,大家合作联调浪费很大,所以必须稳!

image-20230519203620163

如果说问题在Database上,那为什么会有Database RT忽上忽下,Database RT降下去了Tomcat RT不降?我们要继续分析一下 Tomcat RT以及Database RT是怎么记录和实现的

分析

问题解决后的原因分析以及数据整理

这个时候我们再把Tomcat部分的业务调用和RT记录再细化一下,如下图:

image-20230520111102697

Druid分析

创建和回收逻辑:https://exceting.github.io/2019/08/28/%E6%B1%A0%E5%8C%96%E6%8A%80%E6%9C%AF%EF%BC%88%E4%B8%80%EF%BC%89Druid%E6%98%AF%E5%A6%82%E4%BD%95%E7%AE%A1%E7%90%86%E6%95%B0%E6%8D%AE%E5%BA%93%E8%BF%9E%E6%8E%A5%E7%9A%84%EF%BC%9F/#%E4%B9%9D%E3%80%81%E4%B8%BB%E6%B5%81%E7%A8%8B5%EF%BC%9A%E5%9B%9E%E6%94%B6%E8%BF%9E%E6%8E%A5

作为Tomcat和Database的连接点、枢纽点搞清楚Druid的逻辑对理解Tomcat和Database之间的问题的理解很关键。

image-20240523084559029

比如以下要说的三个Druid 错误状态如果你不放到一起比较,看到这个错误你最多反应就是连接池不够了,什么原因不知道。但是如果放到一次比较一次后你以后对详细错误提示会积极敏感,进而发现第四、第五种错误提示

这就是综合比较、总结的好处。

Druid 最核心的类是 DruidDataSource,连接的构建,入池,获取,收缩,销毁,以及核心监控数据都在这个类维护

image-20230721170334688

连接池初始化流程:初始化驱动实例 -> 加锁 -> 初始化属性 -> 初始化过滤器 -> 校验参数 -> 创建初始化连接并校验后加入池中 -> 创建logStatsThread、createConnectionThread和destroyConnectionThread -> 注册MBean,用于支持JMX -> 如果设置了keepAlive,通知createConnectionThread创建连接对象 -> 解锁

Druid 创建连接的堆栈如下:

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
"Druid-ConnectionPool-Create-1647809146" #265 daemon prio=5 os_prio=0 tid=0x00007fbcdfd5f000 nid=0x1a0 runnable [0x00007fbcdf9fd000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:101)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:144)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:174)
- locked <0x00000000e71ca648> (a com.mysql.jdbc.util.ReadAheadInputStream)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3001)
at com.mysql.jdbc.MysqlIO.readPacket(MysqlIO.java:567)
at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:1018)
at com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2253)
at com.mysql.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:2284)
at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2083)
- locked <0x00000000e7f898f0> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:806)
at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
at sun.reflect.GeneratedConstructorAccessor196.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:410)
at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:328)
at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1558)
at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1623)
at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2468)

"Druid-ConnectionPool-Create-1823047135" #160 daemon prio=5 os_prio=0 tid=0x00007fbd60cf0000 nid=0x142 waiting on condition [0x00007fbd043fe000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park0(Native Method)
- parking to wait for <0x00000000c448b348> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at sun.misc.Unsafe.park(Unsafe.java:1036)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:176)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2047)
at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2443)

Druid 报错1

获取连接排队是基本不消耗CPU,下图右上角是获取失败的日志打堆栈消耗,可以看到异常非常多。

image-20230519174633172

image-20230519175029396

Druid最大连接数默认是30,多次调大,30->60->120->160,一直调下去对调大能解决问题都没有信心了,总是报错

maxWaitThreadCount 30, current wait Thread count 0

调大到160后的报错堆栈,对应源码 这个报错说明报错时已经有160个线程在等连接了,别等了,先快速报错返回吧

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
43
44
45
46
47
48
49
50
Caused by: java.sql.SQLException: maxWaitThreadCount 160, current wait Thread count 0
at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1620)
at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1404)
at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5059)
at com.alibaba.druid.filter.FilterAdapter.dataSource_getConnection(FilterAdapter.java:2756)
at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5055)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1382)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1374)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:98)

对应代码:
final Lock lock = this.lock;
lock.lock();
try {
if (activeCount < maxActive) {
activeCount++;
holder.active = true;
if (activeCount > activePeak) {
activePeak = activeCount;
activePeakTime = System.currentTimeMillis();
}
break;
} else {
discard = true;
}
} finally {
lock.unlock();
}

if (discard) {
JdbcUtils.close(pyConnInfo.getPhysicalConnection());
}
}
}

final ReentrantLock lock = this.lock;
try {
lock.lockInterruptibly();
} catch (InterruptedException e) {
connectErrorCountUpdater.incrementAndGet(this);
throw new SQLException("interrupt", e);
}

try {
if (maxWaitThreadCount > 0
&& notEmptyWaitThreadCount >= maxWaitThreadCount) {
connectErrorCountUpdater.incrementAndGet(this);
throw new SQLException("maxWaitThreadCount " + maxWaitThreadCount + ", current wait Thread count "
+ lock.getQueueLength());//bug? lock.getQueueLength()永远为0,应该改成:lock.getWaitQueueLength(notEmpty)
}

以下两个Druid 报错这次压测没有出现但是可以放一起比较一下,其它项目场景经常出现

Druid 报错2

Druid类似报错,明显是等了5秒最大等待时间还没有获取到连接:image-20230519191317489

红色错误信息表示等了5006毫秒(设置的5000毫秒超时)还没有取到连接,所以超时了,然后抛出错误堆栈。

红色信息还提示我们当前连接池最大10,目前 active 0, 说明不是连接池满了取不到,而是连接池里一直是空的。

看到这个错误不能说明数据库、访问数据库有啥问题,只能说明Druid 连接池取不到连接,要继续分析Druid创建连接的线程栈。或者比如Druid 参数设置不合理,可以把min、init、max 连接数设置为相同的值,避免压力高峰期再去创建连接。

Druid通过另外一个task(thread)异步给连接池补充连接,也就是这里可能是Druid创建连接失败,比如密码错误、比如连不上数据库,比如创建的thread卡死了、报其他异常了

Druid创建 连接 和业务取连接是两个线程,所以业务取连接报错是看不到创建连接报错的堆栈和原因的

1
2
3
#grep CreateConnectionThread.run stack4.log
at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2818)
at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2813)

Druid 报错3

image-20230520092224080

借出连接为0(active 0),creating也是0,没有新连接正在创建。

分析方法:

  1. dump Java应用内存,用MAT内存分析工具打开dump文件
  2. 使用OQL,select * from com.alibaba.druid.pool.DruidDataSource where createTaskCount=3
  3. 选出来的DruidDataSource即为有问题的datasource

原因

Druid中有个计数器createTaskCount,用来记录每个连接池当前正在创建连接的任务数,默认不能超过3。Druid中,在keepAlive=true的情况下,这个计数器有bug,存在加了但没减的情况,导致这个值涨到3之后没有减回去,从而无法提交新的创建连接任务。

注意,进入这个状态后的连接池,是无法自动恢复的。Druid升级到1.1.24可以修复这个问题。

Druid 报错 4

下图这个堆栈很有意思,栈顶是连接不够触发 Druid 创建新连接,但是建新连接报错了,于是需要记录日志,但是有些场景(比如任务流) 要求,错误信息要往数据库存,于是记录日志触发取连接,然后就死锁了:

image-20250306153320704

分片逻辑

因为数据量太大,一台Database存放不下,自然会分片,或者说单表几千万之后也是建议分片。

分片逻辑是取业务id最后两位的字符去取string hashcode,再对16个Database分片

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
如果对id后两位字符(从00-99供100个数字,因为不排除id里面有字符,但实际主要是0-9的数字)的ascii码取hash然后按16取模的结果:
0
1
2
3
4
5
6
7
8
9 --开始不正常,10-14号分片没有直接跳到15号分片
15
0
1
2
3
4
5
6
7
8
14
15
……

//分片求模代码
for(int i=0;i<10;++i) //0的ascii码是48,依此类推
for(int j=0;j<10;++j)
int value=((48+i)*31+j) mod 16;

补充个小八卦

为什么取某几位尾数来求模?比如很多业务按user_id拆分片,然后希望这个用户的所有订单拆分也落在一个分片内。于是他们想到的办法是在订单id最后几位上追加进去下单人的user_id后几位,对订单拆分会取订单id后几位hash,这样同一个用户肯定到同一个分片

这样查询某个用户的所有订单时(高频需求)就只需要查一个分片,否则就要扫描所有分片。

掏出你的某宝、某东看看你的订单后几位

分片后的数据,明显两头的多中间的少,这必然导致后面的 Database 负载不均衡:

image-20230519181628114

Java源码:

image-20230519181451384

总结

问题的根本原因?

多个Database中的某几个瓶颈,为什么会这样见数据分布部分的分析

为什么Database RT监控能降下来?

业务Tomcat 帮Database拦截了流量,一旦Database响应慢 Druid 连接就会不够,请求都堵在Tomcat中,导致Tomcat RT升高(包含等待连接时间)——替人堵了枪眼,很好,Tomcat crash总比 Database crash要好,但是业务要清楚这是替人挨枪子,该往哪里去查瓶颈。

比如加流量20%,开始Database RT升高,很快连接不可用,可能有接近20%的流量被Tomcat拦截,这个时候Database RT能稳定,也有可能拦截的不够多,这个时候Database RT还是很高,但Tomcat RT更高,进入一种平衡状态

为什么有时候压测能过?

应该是数据分布比较巧,刚好压测流里面的数据分布没那么不均衡,没触发数据库雪崩

实战瓶颈定位-我的MySQL为什么压不上去–写场景

纠结好久要不要写这篇,因为原因非常坑爹,你们基本不会遇到,想了很久觉得思路还是有些价值,所以还是写一下,我尽量简单

背景

继续上文 https://plantegg.github.io/2023/06/20/%E5%AE%9E%E6%88%98%E7%93%B6%E9%A2%88%E5%AE%9A%E4%BD%8D-%E6%88%91%E7%9A%84MySQL%E4%B8%BA%E4%BB%80%E4%B9%88%E5%8E%8B%E4%B8%8D%E4%B8%8A%E5%8E%BB/ ,纯读场景问题解决后,继续压纯写场景,比另外一套类似环境差了很多,大概是2折。

纯写肯定有预期:会有锁、磁盘瓶颈等问题

分析

先看top,结果很明显CPU上不去,并且有一个单核长时间 100%,然后 top -Hp mysqld-pid 展开所有线程,果然一直有一个线程几乎一直 100%,这就太明显了,这个线程遇到了瓶颈,导致整体上不去。

image-20230515083125494

top -Hp mysqld-pid 看到165935 线程一直几乎是 100% 的CPU 状态

image-20230515083309083

所以接下来要搞清楚这个线程在忙什么,刷盘?抢锁?

如果是Java应用就简单了,直接jstack一看就很清楚了,但是MySQLD没这么容易,另外环境里没有 pstack也没法安装,所以这条路走不通。

但是大概率能猜出来和磁盘有点关系,于是iostat -x -d 看看磁盘情况,好家伙果然ioutil 100%,磁盘 IO TPS 好几万。如下nvme0n1是MySQLD 使用的SSD 数据盘,vdb 是OS 系统盘

1
2
3
4
5
6
7
8
9
10
11
12
#iostat  -d vdb nvme0n1 3
Device: tps kB_read/s kB_wrtn/s kB_read kB_wrtn
nvme0n1 45317.33 37.33 322150.67 112 966452
vdb 0.00 0.00 0.00 0 0

Device: tps kB_read/s kB_wrtn/s kB_read kB_wrtn
nvme0n1 45215.33 37.33 319228.00 112 957684
vdb 0.00 0.00 0.00 0 0

Device: tps kB_read/s kB_wrtn/s kB_read kB_wrtn
nvme0n1 45146.00 42.67 320677.33 128 962032
vdb 0.00 0.00 0.00 0 0

通过 :iostat -x -d vdb nvme0n1 3 可以看到如下图

image-20230515083645463

但这是不是正常情况不好说,于是找到家里同样的环境跑起来(没有单线程 100%问题,QPS 比问题环境高了 5倍),于是也看一下 iostat 做一个对比,对比发现 ioutil 很小,然后磁盘 IO TPS 才我问题环境的30%,在QPS 5倍,IO TPS才 30%的情况下傻子也能看出来这两场景肯定不一样。一个QPS触发的IO TPS差了 15倍了。

不啰嗦,将问题环境的sysbench 脚本复制到正常环境,这下问题重现了,再diff看看两个脚本果然被人改了。问题环境使用的sysbench是别人装的,经过分析后发现里面被改动过一些东西。

之所以一直没有怀疑 sysbench 的问题,也有之前测试只读场景的时候符合预期,所以忽视了sysbench的差异。

这让我想起贝尔实验室Ken Thompson’s “cc hack” 的八卦(有兴趣的同学可以自行查证一下):

当年在贝尔实验室,人们都用Unix系统,但是只有Ken可以绕过密码直接登录,让其他人百思不得其解。按理说整个Unix系统是开源的,很多人检查了系统代码,尤其是登录部分, 并没有发现任何漏洞或者后门。

Ken的同事们不断重新编译Unix, 但是Ken依旧如幽灵一般来去自如。

有人怀疑编译Unix的编译器里面有代码,但是当他们反复检查编译器源码,甚至重新编译c编译器后,依旧没有任何发现。

多年后,在Turing Award Lecture中,Ken终于道出了事情真相,登录源码和编译器源码都是干净的。事实上,这个幽灵般的木马在编译器的可执行文件中。

总结

这里的思路是:单线程100%->磁盘IO TPS非常高->和正常环境对比(常用手段,也要运气好有两个环境可以对比)->一个QPS 对应的IO TPS差异巨大->压测脚本问题

这算是个坑爹的小问题,大家也不会碰到,比网络限速难查多了,网络限速那里我们有放之四海而皆准的 RT 逻辑+抓包,所以很好定位。但是查证分析过程我觉得有一定的参考性,所以记录下。

如果MySQLD能提供一个内部任何一个操作的时间就好了,实际很难实现。当然通过火焰图去看异常偏高的调用是另外一个方向。

跨网络我们有抓包很好界定,但是问题到进程内部的时候反而没了抓包这种一锤定影的工具了

等额本息和等额本金以及提前还贷误区

1 等额本金和等额本息的差异

没有差异。等额本金=等额本息+每月提前还贷一点点()

2 为什么等额本金总利息少

因为每个月等额本金还款多,第一个月后欠本金少了,后面每个月都是这样,所还本金更多,最终总利息自然更少

其实可以用极限思维来分析他们的差异:假设等额本息和等额本金都借100万,周期一个月(没看错,一个月还清,极限假设),所以一个月后他们还钱一样多!所以这个时候没有任何区别;现在继续假设,假如还款周期是2个月,那么等额本金在第一个月还钱多,导致等额本金在第二个月的时候欠钱少了,到第二个月月底还清所有欠款的时候利息要少(本金少了)——这才是他们的差异,所以是没区别的。等额本金这两个月相当于欠了银行150万一个月(第一个月欠100万,第二个月欠50万) 应还利息就是150万 乘以 月利率;等额本息相当于欠了银行 151万(第一个月欠100万,第二个月51万,因为第一个月还钱的时候只还了49万本金),所以应还利息就是 151万 乘以 月利率;欠得多利息就多天经地义这里没有投机、没有人吃亏

再或者换个思路:第一个月借100万,月底都还清,此时利息一样多;然后再借出来99.X万,这时等额本金借得少这个X更小,所以从第二个月开始等额本金还的利息少,归根结底换利息少是因为借得少(即现实中的还本金多)

把上面的极限思维图形化就是下图中的灰色部分面积代表你的欠款(每个月的欠款累加),等额本息的方式欠得多,自然利息多:

image-20230704214346239

3 为什么总有等额本金划得来的说法

同样贷款金额下等额本金总还款额少,也就是总利息少,所以给了很多人划得来的感觉,或者给人感觉利息便宜。其实这都是错的,解释如上第二个问题

4 利息的计算方式

利息每个月计算一次,这个月所欠本金*月利率。所以利息只和你欠钱多少有关(我们假设所有人的利率都一样)。每个月的月供,都是先还掉这个月的利息,多余的再还本金

等额本金因为每个月还掉的本金多,所以计算下来每个月的利息更少

5 如何理解等额本金和等额本息

同样贷款额+利率的话等额本金开始还款一定比等额本息要多一些,那么你可以把等额本金分成两块,一块和等额本息一样,多出来的部分你把他看成这个月额外做了一次提前还款。你提前还款了后面的总利息自然也会更少一些,然后每个月的等额本息也会减少,以此类推每个月都是这样额外做一次提前还款直到最后一个月。

总结:等额本金=等额本息+提前还贷

额本金开始还款一定比等额本息要多一些,可以把等额本金分成两块,一块和等额本息一样,多出来的部分把他看成这个月额外做了一次提前还款。提前还款后总利息也会更少一些,然后每个月的等额本息也会减少,以此类推每个月都是这样额外做一次提前还款直到最后一个月。

6 提前还款划不划得来

钱在你手里没法赚到比利息更高的收益的话(99%的人属于这种)提前还贷划得来,之所以以前不建议大家提前还贷,是因为以前普遍涨薪快、通胀厉害、房价涨得块,把钱留出来继续买二套、三套更赚钱。另外钱留在手里会有主动权和应急方便

7 提前还贷会多付利息吗?

不会,见第四条利息的计算方式。担心提前还贷的时候这比贷款把后面10年的利息收走了的是脑子不好使的人。但有些银行提前还贷会有违约金

8 为什么等额本金和等额本息给了这么多人错觉

从知识的第一性出发,他们都没理解第4条,受社会普遍意识影响都预先留下了错误经验。本质就是利息只和贷款额、利率有关。

9 贷款30年和10年利率有差异吗?

没有

10贷款30年,还了6年了,然后一次还清所有欠款会多还利息吗?

不会,你前6年只是还了前6年的利息,没为之后的6年多付一分利息

11 那为什么利率不变我每个月利息越来越少

因为你欠的钱越来越少了,不是你提前还了利息,是你一直在还本金

12 网购分期合适吗?

大部分小贷公司的套路就是利用你每个月已经在还本金的差异,利息自然越来越少,然后计算一个大概5%的年息误导你,实际这种网购分期的实际利息要是他计算的2倍……好好想想

等额本金、本息都搞不清楚的人就不要去搞分期了,你的脑瓜子在这方面不好使。

聪明人只看第4条就能在大脑里得出所有结论,普通人除了要有第4条还需要去看每个月的还款额、还款额里面的本金、还款额里的利息等实践输入才能理解这个问题,这就是差异

房贷

https://zhuanlan.zhihu.com/p/161405128

提前还贷

要不要提前还贷

提前还贷划得来吗?

划不划得来要看这笔钱在你手里能否获得比房贷利息更高的收入以及你对流动资金的需要。其实万一有个啥事也可以走消费贷啥的,现在利息都很低

等额本息比等额本金提前还贷更划得来?

一样的,你这个问题等价于我欠100万,老婆欠50万,所以我提前还贷比朋友合算吗?显然你两谁提前还贷合算只和你两的贷款利率是否有差别

等额本息和等额本金利率一样的,所以没有差别

20年的房贷我已经还了15年了是不是不值得提前还贷了?

错误!利率还是那个利率,跟你还剩10年和还剩5年没关系,提前还贷都是等价的。记住有闲钱就提前还

问题的本质

搞清楚每个月的利息怎么计算出来的 利息=欠款额*月利率,月供都是把本月利息还掉多出来的还本金,也就是每个月欠款额会变少

总结

每个领域都有一些核心知识点代表着这些问题的本质,你只有把核心知识点或者说问题本质搞懂了才能化繁为简、不被忽悠!

那贷款这里的本质是什么?就是利息只和你每个月欠款以及利率有关!这简直是屁话,太简单了,但你不能理解他,就容易被套上等额本金、等额本息、提前还贷的外壳给忽悠了。

再或者说这里的本质就是:你去搞清楚每个月的还款是怎么计算的。月供=本月所欠X利率+本月还掉的本金 这是个核心公式,差别在每个月还掉的本金不一样!

就这样吧该懂的也该看懂了,看不懂的大概怎么样也看不懂!只能说是蠢,这些人肯定理科不好、逻辑不行,必定做不了程序员。

比如网上流传的如图总结的所有结论都是错的:

image-20230704215506179

实战瓶颈定位-我的MySQL为什么压不上去

背景

环境两台云上相同 128C的EC2(有点豪),一台当压力机一台当服务器,用Sysbench测试MySQL纯读场景,不存在任何修改,也就几乎没有锁

1
2
3
4
5
#uname -r
5.10.84.aarch64

Server: MySQL
Server version: 8.0.18 Source distribution

EC2机器128核,故意只给MySQLD绑定了其中的24Core,网卡32队列

1
2
3
4
5
6
7
8
9
10
11
12
#ethtool -l eth0
Channel parameters for eth0:
Pre-set maximums:
RX: 0
TX: 0
Other: 0
Combined: 32
Current hardware settings:
RX: 0
TX: 0
Other: 0
Combined: 32

img

压测过程

走同一交换机内网IP压MySQL跑不满CPU,跑压力和不跑压力时ping rtt 分别是 0.859/0.053(RTT 有增加–注意点), 此时TPS:119956.67 1000并发 RT 8.33

下图是压测时 htop 看到的MySQLD 所在EC2的 CPU使用情况,右边65-88是MySQLD进程(绿色表示us, 红色表示sys+si CPU)

image-20230511125934259

用top查看详细的每个 core 使用(只展示MySQLD使用的24core ,top 然后按1–还可以试试2/3,有惊喜)

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
top - 13:49:55 up 160 days, 18:10,  3 users,  load average: 555.26, 720.12, 462.21
Tasks: 1065 total, 1 running, 499 sleeping, 0 stopped, 0 zombie
%Node1 : 10.1 us, 5.3 sy, 0.0 ni, 83.3 id, 0.0 wa, 0.0 hi, 1.3 si, 0.0 st
%Cpu64 : 29.3 us, 16.5 sy, 0.0 ni, 54.2 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu65 : 37.0 us, 18.5 sy, 0.0 ni, 26.9 id, 0.0 wa, 0.0 hi, 17.5 si, 0.0 st
%Cpu66 : 34.2 us, 17.8 sy, 0.0 ni, 47.9 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu67 : 26.0 us, 15.1 sy, 0.0 ni, 58.9 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu68 : 26.1 us, 14.8 sy, 0.0 ni, 59.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu69 : 27.2 us, 13.8 sy, 0.0 ni, 59.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu70 : 25.7 us, 11.8 sy, 0.0 ni, 62.5 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu71 : 18.3 us, 10.6 sy, 0.0 ni, 71.1 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu72 : 29.7 us, 12.6 sy, 0.0 ni, 57.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu73 : 21.2 us, 13.0 sy, 0.0 ni, 65.9 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu74 : 18.9 us, 10.8 sy, 0.0 ni, 70.4 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu75 : 28.9 us, 15.1 sy, 0.0 ni, 36.1 id, 0.0 wa, 0.0 hi, 19.9 si, 0.0 st
%Cpu76 : 30.3 us, 15.5 sy, 0.0 ni, 54.1 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu77 : 25.1 us, 13.2 sy, 0.0 ni, 61.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu78 : 18.2 us, 10.3 sy, 0.0 ni, 71.5 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu79 : 14.9 us, 8.8 sy, 0.0 ni, 76.3 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu80 : 23.4 us, 12.2 sy, 0.0 ni, 64.4 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu81 : 35.3 us, 17.6 sy, 0.0 ni, 30.2 id, 0.0 wa, 0.0 hi, 16.9 si, 0.0 st
%Cpu82 : 28.2 us, 16.1 sy, 0.0 ni, 55.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu83 : 37.5 us, 16.9 sy, 0.0 ni, 27.0 id, 0.0 wa, 0.0 hi, 18.6 si, 0.0 st
%Cpu84 : 35.4 us, 18.5 sy, 0.0 ni, 46.1 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu85 : 27.9 us, 16.8 sy, 0.0 ni, 55.2 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu86 : 28.2 us, 13.7 sy, 0.0 ni, 58.1 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu87 : 27.2 us, 11.0 sy, 0.0 ni, 61.8 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu88 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st

继续尝试用2000并发,TPS、CPU、ping rtt都和1000并发没有区别,当然按照我们以前QPS、RT理论2000并发的时候RT应该翻倍,实际确实是16.66,所以这里的问题就是翻倍的 RT哪里来的瓶颈就在哪里

也试过用两个压力机每个压力机分别用1000并发同时压,QPS一样稳定——目的快速排除压力端、链路上有瓶颈。

写到这里RT 刚好翻倍16.66=8.33*2 数字精准得好像编故事一样,不得不贴一下原始数据证实一下:

image-20230511130851332

1000 并发和2000并发时的ping RTT对比(ttl 64说明内网直达)

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
#ping mysqld27
PING yt27 (mysqld217) 56(84) bytes of data.
---以下是2000并发
64 bytes from mysqld27 (mysqld217): icmp_seq=1 ttl=64 time=0.867 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=2 ttl=64 time=0.952 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=3 ttl=64 time=0.849 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=4 ttl=64 time=0.857 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=5 ttl=64 time=0.987 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=6 ttl=64 time=0.860 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=7 ttl=64 time=0.909 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=8 ttl=64 time=0.875 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=9 ttl=64 time=0.979 ms
---终止压测,无无压力的rtt
64 bytes from mysqld27 (mysqld217): icmp_seq=10 ttl=64 time=0.104 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=11 ttl=64 time=0.079 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=12 ttl=64 time=0.075 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=13 ttl=64 time=0.075 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=14 ttl=64 time=0.074 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=15 ttl=64 time=0.078 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=16 ttl=64 time=0.075 ms
---开启1000并发时的rtt
64 bytes from mysqld27 (mysqld217): icmp_seq=17 ttl=64 time=0.872 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=18 ttl=64 time=0.969 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=19 ttl=64 time=0.862 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=20 ttl=64 time=0.877 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=21 ttl=64 time=0.961 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=22 ttl=64 time=0.828 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=23 ttl=64 time=0.098 ms
64 bytes from mysqld27 (mysqld217): icmp_seq=24 ttl=64 time=0.083 ms

抓包证明

在抓保证明前推荐一个工具快速绕过抓包(原理也是通过pcap lib去分析网络包,tcpdump也会调用pcap lib)

监控tcprstat,从网络层抓包来对比两个并发下的RT:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
//./tcprstat -p 3307 -t 1 -n 0 -l 10.9.10.22 -f "%T\t\t%n\t\t%a\t%h\t%S\t%C\t%95M\t%95a\t%95S\t%99M\t%99a\t%99S\n"
#tcprstat -p 14822 -t 1 -n 0 -l mysqld217 -f "%T\t\t%n\t\t%a\n"
timestamp count avg
1683785023 50743 626
1683785024 120004 100
1683785025 120051 103
1683785026 120042 102
1683785027 120031 103
1683785028 120034 104
1683785029 120034 104
1683785030 55209 103 ---以上是2000并发
1683785038 0 0
1683785039 0 0
1683785040 55224 614 ---以下是1000并发
1683785041 119998 104
1683785042 120039 105
1683785043 120039 105
1683785044 120026 107
1683785045 120039 108
1683785046 120047 108
1683785047 120037 108
1683785048 120032 108
1683785049 120041 108

也就是网卡层面确认了压不上去瓶颈不在MySQL 上,加并发后网卡的RT没变(网卡RT包含MySQLD RT),因为ping RTT 在1000和2000并发也没有差异,推测交换机不是瓶颈,大概率出网卡的虚拟层面

在客户端的机器上抓包,上面我们说过了1000并发的RT是8.33毫秒:

image-20230511141508811

注意上图,我把RT排序了,明显看到5ms到17ms 中间没有这个RT范围的包,但是有很多25ms的RT,平均下来确实是8.33毫秒,留下一个疑问:RT分布不符合正态,而且中间有很大一段范围镂空了!这是不应该的。

同样我们再到MySQLD 所在机器抓包分析(注:正常路径先抓MySQLD上的包就行了):

image-20230511141925557

同样是对RT 排序了,但是慢的RT都是对端发慢了(注意最右边的select, MySQL相应是 response),同样对这个抓包求平均时间就是tcprstat 看到的103微秒,也就是0.1毫秒。如下图红框是请求,请求的间隔是11毫米,绿框是响应,响应的间隔都是0.2ms不到

image-20230513084610300

同样在2000并发时也对MySQLD所在网卡抓包对比,response 的RT 没有变化,从这里可以看出瓶颈点在sysbench 和 MySQLD 的网卡之间的链路上,似乎有限流、管控

image-20230512084446715

快速验证

到这里我们已经找到了有力的证据,RT是在离开MySQLD网卡后增加上去的,先验证下走走本机127.0.0.1快速压一把,让sysbench 跑在0-7 core上,这时可以看到MySQL跑满了CPU,下图左边1-8核是压力进程,右边65-88是业务进程,TPS:239969.91 1000并发 RT 4.16

htop状态:

image-20230511125346066

各CPU 详细分析:

  • us MySQL解析SQL、处理查询
  • si 网络软中断
  • sy OS 的sys API 消耗,一般用户进程会调用系统 API, 比如读写文件、分配内存、网络访问等
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
//sysbench
top - 13:44:27 up 160 days, 18:04, 3 users, load average: 792.17, 619.09, 311.58
Tasks: 1073 total, 1 running, 500 sleeping, 0 stopped, 0 zombie
%Cpu0 : 14.0 us, 29.1 sy, 0.0 ni, 33.3 id, 0.0 wa, 0.0 hi, 23.5 si, 0.0 st
%Cpu1 : 12.5 us, 33.0 sy, 0.0 ni, 33.7 id, 0.0 wa, 0.0 hi, 20.8 si, 0.0 st
%Cpu2 : 11.2 us, 32.7 sy, 0.0 ni, 34.2 id, 0.0 wa, 0.0 hi, 21.9 si, 0.0 st
%Cpu3 : 13.4 us, 31.2 sy, 0.0 ni, 34.4 id, 0.0 wa, 0.0 hi, 21.0 si, 0.0 st
%Cpu4 : 12.1 us, 31.3 sy, 0.0 ni, 34.2 id, 0.0 wa, 0.0 hi, 22.4 si, 0.0 st
%Cpu5 : 10.5 us, 31.8 sy, 0.0 ni, 33.6 id, 0.0 wa, 0.0 hi, 24.1 si, 0.0 st
%Cpu6 : 12.9 us, 31.3 sy, 0.0 ni, 34.2 id, 0.0 wa, 0.0 hi, 21.6 si, 0.0 st
%Cpu7 : 12.3 us, 31.4 sy, 0.0 ni, 34.3 id, 0.0 wa, 0.0 hi, 22.0 si, 0.0 st
%Cpu8 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st

//MySQLD
Tasks: 1073 total, 1 running, 505 sleeping, 0 stopped, 1 zombie
%Node1 : 22.6 us, 10.1 sy, 0.0 ni, 62.4 id, 0.0 wa, 0.0 hi, 4.8 si, 0.0 st
%Cpu64 : 57.9 us, 29.1 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 12.9 si, 0.0 st
%Cpu65 : 60.3 us, 26.2 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 13.6 si, 0.0 st
%Cpu66 : 57.6 us, 28.1 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 14.2 si, 0.0 st
%Cpu67 : 60.9 us, 25.5 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 13.6 si, 0.0 st
%Cpu68 : 59.9 us, 26.2 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 13.9 si, 0.0 st
%Cpu69 : 57.9 us, 27.5 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 14.6 si, 0.0 st
%Cpu70 : 61.3 us, 26.2 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 12.6 si, 0.0 st
%Cpu71 : 64.0 us, 23.4 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 12.5 si, 0.0 st
%Cpu72 : 61.3 us, 26.8 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 11.9 si, 0.0 st
%Cpu73 : 63.0 us, 22.8 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 14.2 si, 0.0 st
%Cpu74 : 61.4 us, 27.4 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 11.2 si, 0.0 st
%Cpu75 : 63.9 us, 26.5 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 9.6 si, 0.0 st
%Cpu76 : 61.3 us, 27.2 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 11.6 si, 0.0 st
%Cpu77 : 55.0 us, 30.5 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 14.6 si, 0.0 st
%Cpu78 : 60.9 us, 26.8 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 12.3 si, 0.0 st
%Cpu79 : 58.4 us, 26.7 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 14.9 si, 0.0 st
%Cpu80 : 58.7 us, 29.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 12.2 si, 0.0 st
%Cpu81 : 62.6 us, 27.2 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 10.3 si, 0.0 st
%Cpu82 : 61.9 us, 25.5 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 12.6 si, 0.0 st
%Cpu83 : 58.7 us, 27.4 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 13.9 si, 0.0 st
%Cpu84 : 59.4 us, 27.7 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 12.9 si, 0.0 st
%Cpu85 : 58.9 us, 28.5 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 12.6 si, 0.0 st
%Cpu86 : 58.4 us, 28.4 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 13.2 si, 0.0 st
%Cpu87 : 61.1 us, 27.4 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 11.6 si, 0.0 st

就以上sysbench VS MySQLD 的CPU 消耗来看,因为sysbench 处理逻辑简单,就是发SQL给MySQLD,所以 sysbench自身US很少,大部分都是调用OS的网络操作,而MySQLD有 60% CPU用于US,也就是自身业务逻辑,MySQLD收到SQL要做SQL解析,要去查找数据,这些都是用户态消耗,找到数据后走网络发给Sysbench,这部分是sy

到这里可以拿着证据去VIP通道(土豪+专业的客户得有VIP通道)找做网络管控的了,不会再有撕逼和甩锅

sysbench 结果不是正态分布

把所有请求RT 分布进行图形化,此时平均 RT 8.33,理论上是一个正态分布,下图是有限速时:

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
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
 3.615 |                                         2177
3.681 |** 14738
3.748 |******* 55690
3.816 |************* 109713
3.885 |*************** 121830
3.956 |*************** 124851
4.028 |******************* 154927
4.101 |*********************** 188826
4.176 |*************************** 226206
4.252 |************************************ 302617
4.329 |**************************************** 333310 //这里以4.329为中心符合正态
4.407 |******************************* 257048
4.487 |******************** 163100
4.569 |************ 101785
4.652 |******** 63871
4.737 |***** 43998
4.823 |***** 40854
4.910 |***** 42189
4.999 |***** 41182
5.090 |**** 35652
5.183 |**** 30343
5.277 |*** 28573
5.373 |*** 24763
5.470 |*** 22210
5.570 |*** 21808
5.671 |*** 25606
5.774 |*** 26994
5.879 |*** 24672
5.986 |*** 22087
6.095 |** 18466
6.205 |** 14822
6.318 |** 13688
6.433 |** 15381
6.550 |** 13573
6.669 |* 11325
6.790 |* 9442
6.913 |* 7412
省略一大堆
20.736 |* 11407
21.112 |* 9755
21.496 |* 8957
21.886 |* 9434
22.284 |* 9715
22.689 |** 12774
23.101 |** 17000
23.521 |*** 22937
23.948 |***** 40401
24.384 |******** 65370
24.827 |********** 82186
25.278 |********** 85505
25.737 |*********** 94347 //以25.7附近大概又是一个新正态
26.205 |********** 82958
26.681 |**** 30760
27.165 | 2222
27.659 | 69
28.162 | 16
28.673 | 15
29.194 | 20
29.725 | 17

去掉限速后平均 RT 3.26(比下图中大概的中位数2.71大了不少) 完美正态

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
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
1.857 |**                                       19894
1.891 |*** 23569
1.925 |*** 27912
1.960 |**** 33720
1.996 |**** 39892
2.032 |***** 48289
2.069 |****** 57649
2.106 |******** 69437
2.145 |********* 83611
2.184 |*********** 99507
2.223 |************* 119275
2.264 |**************** 141013
2.305 |******************* 165450
2.347 |********************** 191778
2.389 |************************* 219706
2.433 |**************************** 250885
2.477 |******************************* 278379
2.522 |********************************** 303931
2.568 |************************************* 325777
2.615 |*************************************** 342948
2.662 |**************************************** 354029
2.710 |**************************************** 356295
2.760 |**************************************** 353068
2.810 |************************************** 341345
2.861 |************************************ 324600
2.913 |********************************** 303525
2.966 |******************************* 280221
3.020 |***************************** 255042
3.075 |************************** 230861
3.130 |*********************** 206909
3.187 |********************* 184616
3.245 |******************* 164903
3.304 |**************** 146199
3.364 |*************** 131427
3.425 |************* 117059
3.488 |************ 104954
3.551 |*********** 94404
3.615 |********* 83739
3.681 |******** 75705
3.748 |******** 67944
3.816 |******* 60727
3.885 |****** 53757
3.956 |***** 47053
4.028 |***** 42130
4.101 |**** 38069
4.176 |**** 33666
4.252 |*** 30048
4.329 |*** 26923
4.407 |*** 23886
4.487 |** 21615
4.569 |** 19897
4.652 |** 18458
4.737 |** 17729
4.823 |** 17041
4.910 |** 16011
4.999 |** 16099
5.090 |** 16090
5.183 |** 16393
5.277 |** 16729
5.373 |** 17412

用其他网络业务验证

先测试一下网络下载时的ping:

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
--无流量
64 bytes from 172.16.0.205: icmp_seq=11 ttl=64 time=0.075 ms
64 bytes from 172.16.0.205: icmp_seq=12 ttl=64 time=0.080 ms
--从有网络限速的机器下载,带宽100MB
64 bytes from 172.16.0.205: icmp_seq=13 ttl=64 time=0.738 ms
64 bytes from 172.16.0.205: icmp_seq=14 ttl=64 time=0.873 ms
64 bytes from 172.16.0.205: icmp_seq=15 ttl=64 time=0.993 ms
64 bytes from 172.16.0.205: icmp_seq=16 ttl=64 time=0.859 ms
64 bytes from 172.16.0.205: icmp_seq=17 ttl=64 time=0.892 ms
64 bytes from 172.16.0.205: icmp_seq=18 ttl=64 time=0.972 ms
64 bytes from 172.16.0.205: icmp_seq=19 ttl=64 time=1.05 ms
64 bytes from 172.16.0.205: icmp_seq=20 ttl=64 time=0.973 ms
64 bytes from 172.16.0.205: icmp_seq=21 ttl=64 time=0.997 ms
64 bytes from 172.16.0.205: icmp_seq=22 ttl=64 time=0.915 ms
64 bytes from 172.16.0.205: icmp_seq=23 ttl=64 time=0.892 ms
64 bytes from 172.16.0.205: icmp_seq=24 ttl=64 time=0.960 ms
64 bytes from 172.16.0.205: icmp_seq=25 ttl=64 time=1.05 ms
64 bytes from 172.16.0.205: icmp_seq=26 ttl=64 time=0.089 ms
64 bytes from 172.16.0.205: icmp_seq=27 ttl=64 time=0.097 ms
64 bytes from 172.16.0.205: icmp_seq=28 ttl=64 time=0.081 ms
--从没有网络限速的机器下载,带宽1000MB
64 bytes from 172.16.0.205: icmp_seq=29 ttl=64 time=0.078 ms
64 bytes from 172.16.0.205: icmp_seq=30 ttl=64 time=0.077 ms
64 bytes from 172.16.0.205: icmp_seq=31 ttl=64 time=0.073 ms
64 bytes from 172.16.0.205: icmp_seq=32 ttl=64 time=0.072 ms
64 bytes from 172.16.0.205: icmp_seq=33 ttl=64 time=0.079 ms
64 bytes from 172.16.0.205: icmp_seq=34 ttl=64 time=0.074 ms
64 bytes from 172.16.0.205: icmp_seq=35 ttl=64 time=0.080 ms
64 bytes from 172.16.0.205: icmp_seq=36 ttl=64 time=0.077 ms

有限速方向,尝试了BBR和cubic 拥塞算法:

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
#tcpperf -c 172.16.0.205 -t 100
Connected mysqld217:51254 -> 172.16.0.205:2009, congestion control: cubic
Time (s) Throughput Bitrate Cwnd Rwnd sndbuf ssthresh Retr CA Pacing rtt/var
0.000s 0.00kB/s 0.00kbps 14.3Ki 41.3Ki 85.0Ki 2048Mi 0 0 65.2Mi 427us/213
1.029s 122MB/s 975Mbps 1595Ki 1595Ki 9512Ki 576Ki 0 0 123Mi 15.2ms/8
2.005s 105MB/s 843Mbps 1595Ki 1595Ki 9512Ki 576Ki 0 0 123Mi 15.2ms/10
3.010s 105MB/s 843Mbps 1595Ki 1595Ki 9512Ki 576Ki 0 0 123Mi 15.2ms/17
4.016s 105MB/s 843Mbps 1595Ki 1595Ki 9512Ki 576Ki 0 0 123Mi 15.2ms/13
5.022s 105MB/s 843Mbps 1595Ki 1595Ki 9512Ki 576Ki 0 0 123Mi 15.2ms/14
6.028s 105MB/s 842Mbps 1595Ki 1595Ki 9512Ki 576Ki 0 0 123Mi 15.2ms/17
7.003s 105MB/s 843Mbps 1595Ki 1595Ki 9512Ki 576Ki 0 0 123Mi 15.2ms/15
8.009s 105MB/s 843Mbps 1595Ki 1595Ki 9512Ki 576Ki 0 0 123Mi 15.2ms/13
#tcpperf -c 172.16.0.205 -t 100
Connected mysqld217:51932 -> 172.16.0.205:2009, congestion control: bbr
Time (s) Throughput Bitrate Cwnd Rwnd sndbuf ssthresh Retr CA Pacing rtt/var
0.000s 0.00kB/s 0.00kbps 14.3Ki 41.3Ki 128Ki 2048Mi 0 0 98.0Mi 406us/203
1.011s 120MB/s 957Mbps 271Ki 2281Ki 10.4Mi 560Ki 2244 0 108Mi 2427us/11
2.033s 104MB/s 831Mbps 271Ki 2281Ki 10.4Mi 560Ki 1056 0 109Mi 2417us/18
3.021s 104MB/s 830Mbps 274Ki 2281Ki 10.4Mi 560Ki 1056 0 109Mi 2428us/18
4.014s 103MB/s 827Mbps 271Ki 2281Ki 10.4Mi 560Ki 1452 0 108Mi 2423us/19
5.031s 104MB/s 835Mbps 274Ki 2281Ki 10.4Mi 560Ki 660 0 80.2Mi 2435us/22
6.033s 102MB/s 818Mbps 271Ki 2272Ki 10.4Mi 560Ki 2112 0 109Mi 2426us/17
7.030s 103MB/s 823Mbps 274Ki 2281Ki 10.4Mi 560Ki 1716 0 117Mi 2430us/18
8.023s 103MB/s 826Mbps 274Ki 2281Ki 10.4Mi 560Ki 1452 0 109Mi 2428us/20
9.016s 103MB/s 827Mbps 271Ki 2281Ki 10.4Mi 560Ki 1452 0 108Mi 2423us/15

跑tcpperf触发限速时的监控(上下两个窗口是同一台机器),红色是丢包率挺高的,绿色丢包就没了,应该是拥塞算法和限速管控达成了平衡

image-20230511215940306

反过来限速被我去掉了(限速可以进出双向单独控制)

1
2
3
4
5
6
7
8
9
10
11
#tcpperf -c mysqld217 -t 1000
Connected 172.16.0.205:32186 -> mysqld217:2009, congestion control: bbr
Time (s) Throughput Bitrate Cwnd Rwnd sndbuf ssthresh Retr CA Pacing rtt/var
0.000s 0.00kB/s 0.00kbps 14.3Ki 41.3Ki 128Ki 2048Mi 0 0 100Mi 397us/198
1.001s 1107MB/s 8859Mbps 471Ki 985Ki 4641Ki 277Ki 0 0 1083Mi 390us/22
2.001s 1103MB/s 8823Mbps 465Ki 985Ki 4641Ki 277Ki 0 0 1089Mi 393us/16
3.000s 1111MB/s 8892Mbps 465Ki 985Ki 4641Ki 277Ki 0 0 1072Mi 403us/25
4.000s 1099MB/s 8789Mbps 459Ki 985Ki 4794Ki 277Ki 0 0 799Mi 399us/18
5.001s 1098MB/s 8786Mbps 459Ki 985Ki 4794Ki 277Ki 0 0 1066Mi 387us/12
6.000s 1100MB/s 8799Mbps 462Ki 974Ki 4794Ki 277Ki 0 0 1069Mi 399us/16
7.001s 1135MB/s 9078Mbps 453Ki 985Ki 4794Ki 277Ki 0 0 1059Mi 377us/19

查看限速配置如下:

1
2
3
4
5
6
{txcmbps:844.000, txckpps:120.000}

//限速解释
0-31 我猜这是网卡队列(可以修改);
txcmbps:844.000 105.5MB/s 每秒带宽105.5MB
txckpps:120.000 120K packet/s 每秒12万网络包

sysbench(主键查询-小包) 12万QPS 正好命中 txckpps:120,tcpperf (大包)稳定的105MB带宽命中txcmbps:844

去掉后长这样:

1
2
3
4
#ovsctl -n set_out_pps -v -1  //把pps限制为-1==不限制
#ovsctl set_tx -p {} -r -1; //带宽不限制

{vport: 2 {map: 0, prio:L, weight: 0}meter: {-}queue: [ 0- 31L]}

对这块网络管控感兴趣可以去了解一下 ovs 这个开源项目(open virtual switch)

去掉网卡限速后的结果

实际结构如下:

image-20230513132101185

放开所有网络控制后,1000并发压力 30万QPS,RT 3.28,此时从sysbench 以及空闲机器ping MySQLD机器的 RTT和没压力基本一致

image-20230512090205685

top状态:

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
%Node1 : 23.4 us, 12.3 sy,  0.0 ni, 61.4 id,  0.0 wa,  0.0 hi,  3.0 si,  0.0 st
%Cpu64 : 63.2 us, 36.8 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu65 : 44.4 us, 21.9 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 33.8 si, 0.0 st
%Cpu66 : 66.6 us, 33.4 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu67 : 63.4 us, 36.6 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu68 : 64.2 us, 35.8 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu69 : 64.9 us, 35.1 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu70 : 66.6 us, 33.4 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu71 : 65.3 us, 34.7 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu72 : 67.7 us, 32.3 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu73 : 63.6 us, 36.4 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu74 : 66.7 us, 33.3 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu75 : 42.4 us, 19.9 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 37.7 si, 0.0 st
%Cpu76 : 63.9 us, 36.1 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu77 : 67.0 us, 33.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu78 : 68.3 us, 31.7 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu79 : 64.9 us, 35.1 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu80 : 65.2 us, 34.8 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu81 : 44.4 us, 21.5 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 34.1 si, 0.0 st
%Cpu82 : 63.9 us, 36.1 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu83 : 44.2 us, 23.4 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 32.3 si, 0.0 st
%Cpu84 : 65.7 us, 34.3 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu85 : 68.3 us, 31.7 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu86 : 67.5 us, 32.5 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu87 : 62.4 us, 37.6 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu88 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st

image-20230512092713141

小思考:

我们中间尝试走本机127.0.0.1 压测时QPS 是24万,比跨机器压的 30万打了8折,想想为什么?网络延时消耗完全没影响?

总结

简单可复制的证明办法:抓包,快速撕逼和分析

肯定有很多人想到:内存、磁盘、线程池、队列、网络等等原因,但是这些所有原因有一个共同的爹:RT,所有这些影响因素最后体现出来就是RT 高了,你CPU资源不够、内存慢最后总表现就是在客户端看来你的 RT 太高。

所以我们去掉这些复杂因素先在MySQLD所在EC2 的网卡上抓一个包看看RT,再对比一下1000/2000并发时抓包看到的 RT 有没有升高,如果有升高说明问题在MySQLD这端(含OS、MySQLD的问题),如果 RT 不变那么问题不在MySQLD这端,并且从EC2网卡出去都是很快的,那么问题只能是在路上或者客户端的sysbench自己慢了。

这是我们星球里说的无招胜有招–抓包大法,扯皮过程中我还没见过几个不认网络抓包的,也有那么一两个扯上是不是网卡驱动有问题,我的代码不会有问题

两个限速条件:pps 120k(每秒最多12万网络包),带宽 844mbps=105.5MB/s

Sysbench 查询都是小包,触发第一个条件,tcpperf触发第二个条件

ping ping神功失效了吗?也没有,我后来又测试了100、200并发,rtt 0.2ms和0.4ms,也就是说随着并发的增加rtt 增加到0.8ms后就不再增加了。上来1000并发已经到了天花板

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
64 bytes from polardbxyt27 (mysqld217): icmp_seq=159 ttl=64 time=0.226 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=160 ttl=64 time=0.334 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=161 ttl=64 time=0.336 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=162 ttl=64 time=0.213 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=163 ttl=64 time=0.104 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=164 ttl=64 time=0.096 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=165 ttl=64 time=0.101 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=166 ttl=64 time=0.116 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=167 ttl=64 time=0.104 ms--以上 100并发,QPS 119K
64 bytes from polardbxyt27 (mysqld217): icmp_seq=168 ttl=64 time=0.093 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=169 ttl=64 time=0.088 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=170 ttl=64 time=0.405 ms--以下 200并发,QPS 119K
64 bytes from polardbxyt27 (mysqld217): icmp_seq=171 ttl=64 time=0.419 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=172 ttl=64 time=0.386 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=173 ttl=64 time=0.474 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=174 ttl=64 time=0.462 ms
64 bytes from polardbxyt27 (mysqld217): icmp_seq=175 ttl=64 time=0.410 ms
0%