BM-SC MDF-CP Tricky Performance TR Analysis Process

背景

MDF-CP是BM-SC中部署在JBoss上的JEE程序，会给eMBMS gateway 发送sgmb diameter消息，其中sgmb_rar_start是session开始的一个重要标示。所以该消息不能有太大延迟。

SM定义了KPI要求，必须不能大于500ms.

MDF-CP还会通过RTSP协议给MDF-UP发送消息，其中有一个RTSP_PLAY通知MDF-UP哪些content要开始播了。这个消息也不能有太大延迟，否则客户那边到节目开始时会有黑屏。

而这次的三个TR，于此相关。

1. rar_start延迟大于1s,并且比例超过20%

2. rtsp_play延迟大于1s，最大值甚至超过12s，比例同样大于20%

3. 在另外的traffic mode下，600 session并发情况下发送删除session请求，会出现错误。

软性经验

这次分析过程持续了超过一个月，整个NA forum都参与进来讨论这个tricky tr,结果却令人大跌眼镜，我们从老版本release切换成最新版来做测试，两个延迟的tr莫名其妙没有了……让人无比抓狂。

但考虑到这次分析过程还是比较宝贵，为以后类似performance问题的分析提供了参考。所以记下一些总结性的经验。

1. Performance问题在分析过程中，一定要有详尽的log！并且必须通过这些log进行数据挖掘分析。

我们在分析的初期，虽然也分析了现有的log，以及添加了一些简单的log信息，但是不是非常的详尽。结果两个礼拜没有把握到问题的重点。后来，为了得到进一步的数据，才添加了非常详细的跟我们分析问题相关的log，然后用Execl的import功能将这些log导入到Execl中，图形化进行数据分析，靠两个相对值相减来避免系统误差。

２.先排除外因，再往系统内部看。

在看到有误差时，因为统计信息来源于另外一台机器，我们曾怀疑过两边机器之间的一些通信、NTP 时间不对等，发现都没有，就跳过了这个环节。结果，在数据分析后，发现原来还是因为统计机器这边在发送请求的xml里面，对于xsd:dateTime的时间转换是错误的。

根据ISO8601 2004version，xsd:dateTime格式应该是   '-'? yyyy '-' mm '-' dd 'T' hh ':' mm ':' ss ('.' s+)? (zzzzzz)?

即是：

Value = 2 + 4 * (

                                Milliseconds + 1000* (

                                                Seconds + 60 * (

                                                                Minutes + 60* (

                                                                                Hour + 24 * (

                                                                                                Day – 1 + 31 * (

                                                                                                                Month – 1 + 12 * (

                                                                                                                                Year + 9999 ) ) ) ) ) ) )

也就是说，2000-12-12:01:01.65中的.65其实是 .65*1000ms = 650ms, 而.065是0.065*1000ms=65ms.

统计的那台机器上发送请求的程序中，混淆了.65和.065，造成了500ms左右的普遍误差，将这个普遍误差修复后，情况立刻好了很多。

3. 用分支线来显示出当前方向，清晰的记载每个方向中action的内容

Performance的问题，解决起来方向可能会很多，刚开始不记录还好，但是到后面就会混乱起来。某个方向到底测过没，测的结果是什么，还能再查看结果吗？一系列问题。

所以，把每一步标示出来，每一步的结果和统计信息清晰记录，对整个分析过程有一个清晰的思路，不仅对接下来的分析有帮助，对handover和report也是很好的input.

分析过程中学到的知识

1. EJB中的TimerService，并不适用于对时间精度要求非常高的请求。它并不保证实时，也不保证一定在确定时间触发。

在EJB3.1的中有定义：

Section 18.1 Timer Service Overview

The EJB Timer Service is a coarse-grained timer notification service that is designed for use in the mod- eling of application-level processes. It is not intended for the modeling of real-time events.

While timer durations are expressed in millisecond units, this is because the millisecond is the unit of time granularity used by the APIs of the Java SE platform. It is expected that most timed events will correspond to hours, days, or longer periods of time.

 

Section 18.2.5.3

The container interleaves calls to a timeout callback method with the calls to the business methods and the life cycle callback methods of the bean. The time at which a timeout callback method is called may therefore not correspond exactly to the time specified at timer creation. If multiple timers have been created for a bean and will expire at approximately the same times, the Bean Provider must be prepared to handle timeout callbacks that are out of sequence. The Bean Provider must be prepared to handle extraneous calls to a timeout callback method in the event that a timer expiration is outstanding when a call to the cancellation method has been made.

但是，一般容器可以通过tuning来让timer尽量的满足实时和定时的要求，误差可以控制在500ms以内。

容易会给TimerService派发一个线程池，timer队列callback时，由容易从线程池内取线分配给timer。当线程池资源紧张时，timer callback的延迟具有传递性，即上一个timer如果callback花了很长时间,比如两秒，那么这两秒会使得后面timer都延迟两秒。直至没有timer需要紧接着第一个timer触发。

2. JBOSS7中，在用JNDI lookup时，如果是同一个JVM,用remote接口的JNDI NAME，会放大transaction delay。

虽然已被证实，但这个的原因至今未知，JBOSS自己的人也没搞清楚。以后在设计的时候尽量避免。