上周收到分公司同事反映tribonsem速度很慢,影响工作效率。领导派遣xx,xx还有我前去调查情况。我们在二号线并没有找到sem速度慢的实例,只找到了两个tribon的问题。经过我们采集数据并进行分析,初步给出的结论如下。

一:tribon Show Surrounding Models功能缓慢

问题描述:

经过测试,载入模型、旋转和渲染功能都很流畅,只有在使用调取模型周围模型的功能时,会出现较慢的反映。

 

  1. 问题初步分析:

同样的软件在不同环境下有不同的性能表现,比较直接的思路就是去辨别究竟是哪个环境上的差别导致了问题的出现。最容易想到的环境区别就是网络差异,***和局域网在吞吐量(带宽)和时延差异巨大。第一我们需要找到问题究竟是带宽瓶颈还是时延瓶颈。如果是带宽原因那么增加带宽就可以解决问题,如果是时延原因就比较麻烦,因为***的时延是天然存在的,只能通过软件本身来减小时延的影响。第一反应倾向于延时,因为***的带宽是共享的,使用人数不同的时候性能差异会很大,既然用户并没有反映出现性能抖动的现象,带宽瓶颈的可能性并不高。

 

数据采集和分析过程:

速度慢只是一种心理反映,是否真的慢,慢多少需要实际的数据证据,同时我们也需要数据来证明自己的猜测。

我们在本部和分公司分别截取了问题出现时的网络数据,通过比较两组数据的差异,我们就可以找到问题发生的原因。

 

这两组数据的统计摘要如下:

 

分公司

 

 

 

 本部:

 

 

数据说明:

这两组数据的关键部分是最下方的display栏中的displayed部分,这部分是tribon的客户端同服务器端的交互数据统计。我们连接的是同一台服务器,也就是ip地址为172.16.101.33t1309服务器,不过两次调用的模型不同。因为症状是模型无关的,所以我们忽略这个影响。我们可以看到最关键的差别在于数据传输的速度。二号线的速度是1.295Mbit/s,而外高桥能达到5.484Mbit/s。本部的速度是分部的4.23倍。最直接的猜测是由于带宽瓶颈。带宽瓶颈所表现出的特征是瓶颈处的流量始终处于峰值状态,才能保证任何时刻都网络访问速度都缓慢。同时带宽瓶颈会表现出不分应用的网络丢包。因为在没有qos(优先级)情况下的网络接口在出现接近带宽瓶颈的时候会对数据包采取随机丢弃的策略。不会出现有的功能正常,其他功能异常的情况。

 

本部至分部的接口数据如下:

 

Peak value of input: 7246733 bytes/sec, at2014-05-28 08:50:21

Peak value of output: 19571139 bytes/sec,at 2014-05-09 07:03:32

Last 300 seconds input:  1264 packets/sec 355256 bytes/sec 0%

Last 300 seconds output:  1655 packets/sec 1252578 bytes/sec 1%

 

可以很清楚的看见,在当前察看网络状态的时候,网络流量和峰值流量差了一个数量级。

既然如此,那么这个差异究竟是怎么产生的,我们继续察看具体的数据。

 

分部的数据部分截图:

  

 

本部部分的数据截图:

 

 

数据说明:

我们看到这两段数据最明显的差异在相邻的ip方向相反两个报文的时间差,也就是传输时延。

这里需要注意我的说法,因为相邻的ip方向一致的时间差并不表示传输延时,而表示的发送延时。发送延时的上限取决于客户端应用程序想要发送的数据量,以及客户端电脑的网卡工作频率。这个影响目测就可以看出差距来并不大。

而最关键之处在于网络两端一次交互的时间差,专业的说法就是RTT(round trip time-报文往返时间)。在相同数据量的情况下,网络两端相互交互的次数越少,数据的传输速度越快。减少数据交互次数有两个办法,一是增加每个报文的大小,二是一次批量发送多个报文。这两种方法都可以有效的增加网络速度。

根据这个思路,我们再来看下一组数据对比。两地RTT区别:

分部:

 

本部:

 

 

需要注意的是两组数据的单位是不同的。

同时这部分包括了服务器计算上的时延,因此rtt=网络传输时延+计算时延

按照统计学的相关理论,E(x+y)=E(x)+E(y),即两个随机变量的和的期望具有线性性质。

因为我们采集数据的时间段是类似的,因此我们可以假设两次统计计算时延的数学期望(即统计的平均值)是相等的。因此网络延时的期望的差值就等于两次统计的rtt的差值。

在图中可以看出本部的RTT数据集中在2ms以下区间,而分部则高得多,集中在10ms以下。在假设分布均匀的情况下,平均值的差距在4ms左右。比较符合网络实际性能差别的预期。

另外我们可以看到无论是分部还是在本部超高的RTT值是非常零星的,无可以得到的结论是网络的稳定性较好,极少出现丢包的情况。另外需要说明的是,网络上确认是否丢包的依据是和RTT有关的参数RTO,而RTO的协议最小值为200ms,显然和上图中的数据不符。

 

因此凭借对图形的目测就可以可以得出结论,即对于该应用来说网络性能是正常的。

 

既然网络并无异常,那我们继续去挖掘网络性能的差异是如何造成应用的性能差异。我们再看一下两组数据的数据包长度分布统计。

 

分部:

 

本部:

从这两份统计数据来看,两次数据统计都呈现出一个相似的特征,即长度在80-159字节的数据占数据包占全部统计的一半左右。我再解释一下这个数据的意义。

对于一个标准的以太网网络,标准数据包的最小单位是64bit,而以太网帧头占18字节,ip协议头占20字节,tcp协议头占20字节。也就是说在没有任何数据需要传输的情况下,就需要消耗掉48个字节的数据。对于一个160字节的数据包,有效数据容量在70%左右。而标准的以太网帧的最大长度可达到1518字节。可见,这个数据包的大小是非常小的。另外,对于通常的IO而言,每次传输数据的时间=时延+单次传输数据量/带宽,并且传输的总时间=传输次数*单次传输时间,传输次数=总数据量/单次传输数据量,把公式整合,可以得到传输总时间=数据总量*时延/单次传输数据量+数据总量/带宽,时延和带宽是被硬件决定的,所以可以看成一个常量,而数据总量是固定的,因此为了减少总的传输数据时间,需要增加每次传输的数据量。由此可以知小数据包在IO上有天然的弱势。

同时,还有一个因素也产生了一定的影响,因为每次数据传输都会伴随着一次应用程序从用户态至内核态的转换,这也是需要花费一定的时间的。

但是问题的关键不仅仅在于有效容量的降低,关键之处在于上文说的网络数据的传输模式不同于一般的IO传输。

这个数据的传输模式是传输一组数据,等待确认后再传另一组数据。这样,会话次数会随着报文的减小以rtt为系数线性增长。一般较为优化的网络传输通常采用流水线的方式传递数据。能够更有效的利用带宽,而这个程序没能做到这点。

根据推断这极有可能是性能差异的主要原因。

 

数据包非常小的原因有两种情况,一是数据本身比较小,二是数据比较紧急,需要立刻发出去。网络编程接口的默认值是第一种情况,但是程序员可以通过附加参数的方式来进行紧急推送,即第二种情况。

对于默认的情况,网络系统会采用Nagle算法来协调网络时延和吞吐量之间的关系。

这个算法很好理解。比如很多人排队一起坐电梯,最优吞吐量的办法是等人上满电梯才运行。但是这样所付出的代价是已经在电梯里面的人需要等外面的人才能走,会增大延时。而最低时延的办法是电梯上来一个人立刻就走,但是因为每次只能载一个人,所以整体的吞吐量就会下降。Nagle算法就是一个牺牲单个数据包时延的方式来获取更大吞吐量的方法。

我们所需要确认的是导致问题产生的原因是否是由于落入了第二种情况。

因为如果是默认情况,我们只需要修改操作系统的tcp协议中Nagle算法的参数就可以进行调整,而如果陷入了第二种情况,则需要在程序中进行调整。

从网络角度,我们可以通过数据包tcp协议头的flag字段的push位来辨别是否该数据是强制推送的。

因此我们有了下一步的思路,去寻找psh1200字节以下的小数据包,观察里面究竟承载了什么样的数据。

 

因为两边的数据模式极为相似,因此我只截取分部的部分,如下图:

 

 

对这部分数据进行统计的结果如下:

 

 

把上述统计同最初的统计作对比,我们可以发现以下问题:

  1. 满足条件的数据包超过整体包数的60%以上。

  2. 传输的时间贯穿整个会话。

  3. 小包数据总量占整体数据的量非常小。因此可以确定主要数据部分是以大包进行发送的。但。但是小包的数量非常多,因此拖累了整体的网络性能。

 

经观察,小数据包的数据模式非常固定。可以肯定的是,这是一些固定的数据结构。猜测包含了一些模型的元数据,以及一些固定的消息。

例如下面的数据样本:

0000  44 37 e6 5a 32 ed 50 3d e5 a8 78 3f 08 00 45 00  D7.Z2.P=..x?..E.

0010  00 a0 09 46 40 00 7d 06 c4 6f ac 10 65 21 0a 16  ...F@.}..o..e!..

0020  14 5b 02 99 03 3f 91 da 22 93 19 35 54 d0 50 18  .[...?.."..5T.P.

0030  f5 c8 e3 e1 00 00 80 00 00 74 34 1d f7 81 00 00  .........t4.....

0040   00 01 0000 00 00 00 00 00 00 00 00 00 00 00 00 ................

0050   00 00 0000 00 50 00 00 00 50 31 33 30 39 3d 54 .....P...P1309=T

0060   42 31 3333 3d 44 4d 32 30 20 20 20 20 20 20 20 B133=DM20      

0070   20 20 2020 00 00 d4 b5 00 00 5e a0 d3 52 91 00     ......^..R..

0080   00 00 0000 c2 01 01 00 06 00 00 00 00 00 00 00 ................

0090   00 00 0000 00 00 01 00 00 00 00 00 00 00 00 00 ................

00a0   00 00 0000 00 00 00 00 00 00 00 00 00 00       ..............

 

灰色部分为实际的用户数据,采用ascii解码可以看到有p1309=TB133=DM20字样,之前和后面的数据应该是填出数据和其他的数据类型。

 

结合上述证据,我推断第一个问题产生是由于tribon本身应用程序在该功能上对于慢速网络优化不足导致的。如果推断属实,那么最佳的办法是把服务器迁移到本地。至于起到缓存作用的网络加速设备是否能够降低延时则取决于应用程序的交互模式是否允许这样做,可以试一下。

二.切割指令速度缓慢

问题描述:

在执行切割指令操作的时候,会等待非常久的时间才会有反应。

 

初步诊断:

这个问题的诊断思路和上一个问题比较相近,通过比较捕获来数据包来确定问题出现的范围。但是在截获数据包的过程中发生了奇怪的现象,命令还没有执行完毕,刚开始卡在沙漏状态的时候,到目标1309目标服务器的网络已经没有数据了。因此,问题范围从网络转移到了本地计算机。

于是,我拿出了procmon来对该进程进行监控,发现了这时候改进成正在向tech9写入数据。

如图:

 

 

 

 

 

统计信息如下:

 

 

我们在本部也截取了同一个操作的数据,如下图:

 

 

这两组数据里面,可以得到对于这个gen文件的写入,分部的速度为1758 byte/s,而本部的速度为12099 byte/s。本部的速度为分部的6倍。但是实际上,对于一个写入文件这种操作来说,本部的速度也非常低。

需要注意的是这两个操作所截取的写入事件数量都是非常之高的,并且每个事件的数据量很小。

 

这样,就可能有两个原因:

  1. tech9IO可能有问题。

  2. 程序的写入模式可能存在问题。

 

验证方法比较简单,我写了一个测试程序用来测试tech9写入是否存在异常。

 

测试代码如下:

#testwrite.py

 

from random import choice

from string import letters

 

def test():

           writetimes=10000

           testfile=r'z:\testfile'

           f=open(testfile,'w')

           fori in range(writetimes):

                     f.write(choice(letters))

           f.close()

 

if __name__=='__main__':

           test()

 

我把tech9映射成本地磁盘,分1000次向testfile中写入随机字母的数据。

 

Procmon监测的结果如下:

 

很显然,对于一个标准的文件写入程序来说,tech9的表现是完全正常的。现在我想办法模拟tribon写入文件时的系统表现,就是写入能截获的系统event数量非常高。这样,从文件写入原理上来讲,程序会先把要写入的文件放在内存缓冲区里面,再把缓冲区的数据同步到硬盘上面。

每次内存和硬盘交互,可以由flush操作触发。因此我们不断地flush缓冲区,看看系统的表现如何。

测试代码如下:

from random import choice

from string import letters

 

def test():

           writetimes=10000

           testfile=r'z:\testfile'

           f=open(testfile,'w')

           fori in range(writetimes):

                     f.write(choice(letters))

                     f.flush()

           f.close()

 

if __name__=='__main__':

           test()

 

我在每次写入的时候,调用了flush操作,把缓冲区写入到硬盘。

Procmon的监控结果如下:

性能统计如下:

 

可以看到,同样的文件,因为不同的写入方式,前者的时间是0.0079s,而后者是到30.988s。这个原理和上一个问题的原理类似。

 

并且这个测试程序从系统事件上完全再现了tribon的表现。

 

因此,可以由此猜测,第二个问题产生的原因极有可能是由于tribon在写入文件时过度地进行同步操作。并非是tech9io问题引起的,最早我的猜测过度草率了。

 

由此看来,即使切换文件服务器,可能也是无济于事的。