从日志分析ArcGIS Server动态出图的效率【转载】

原文地址：http://blog.csdn.net/xiaoyaohu0325/article/details/6077232

 

前段时间接到一个棘手的问题，用户在使用动态地图服务时，随着平移操作的增加，响应时间也逐渐上升。从最初的零点几秒，一直上升到四五秒，并且还有不断上升的趋势。

    ^{为了重现这个问题，需要先把服务器的日志清空（避免其他信息的干扰），然后通过Manager只启动要观察的动态地图服务，并把日志级别设置成最高的verbose，接下来通过JavaScript API程序访问动态的地图服务，缩放到一定级别以后一直进行平移操作，直到在Firebug里看到响应时间明显上升以后，停止操作。}

    ^{这个时候已经生成了5个10M（ArcGIS Server日志默认的最大字节数）左右的日志，为方便分析，先用cat命令把这些日志合并成1个文件。这就是我们的原材料，接下来用它生成各种各样的产品。}

    ^{1、动态地图输出的时间，每次动态地图输出完成以后，在日志里都会记录这样一条信息（一些无关的信息我用***表示），其中elapsed字段就是这次ExportMapImage耗费的时间：}

^{<Msg time='***' type='INFO3' code='10011' target='***' methodName='MapServer.ExportMapImage' machine='***' process}='5272' thread='24' elapsed='1.39874'>End ExportMapImage</Msg>

      用‘cat **.dat |grep “End ExportMapImage” > export_elapsed.log’命令可以从合并的日志中导出所有动态地图输出完成以后的日志信息。在UltraEdit编辑器里打开export_elapsed.log文件，切换到“列模式”，就可以把所有的elapsed值筛选出来，通过Excel可以生成一个直观的图表。

   2、动态服务每个图层的绘制时间。每次动态绘制，总是以Begin ExportMapImage开始，以End ExportMapImage结束。通过观察这两个标记之间的日志，我发现每个图层绘制总是有以下几个步骤：Execute Query, Symbolizing, Data Access和Symbol Drawing

<Msg time='***' type='INFO3' code='103000' target='***' methodName='Map.Draw' machine='***' process='5741' thread='24'>Beginning of layer draw: LAYER0</Msg>            
<Msg time='***' type='INFO3' code='103024' target='***' methodName='Map.Draw' machine='***' process='5741' thread='24' elapsed='0.00351'>Execute Query</Msg>                            
<Msg time='***' type='INFO3' code='103024' target='***' methodName='Map.Draw' machine='***' process='5741' thread='24' elapsed='0.00000'>Symbolizing</Msg>                              
<Msg time='***' type='INFO3' code='103024' target='***' methodName='Map.Draw' machine='***' process='5741' thread='24' elapsed='0.00782'>Data Access</Msg>                              
<Msg time='***' type='INFO3' code='103023' target='***' methodName='Map.Draw' machine='***' process='5741' thread='24' elapsed='0.00321'>Symbol Drawing</Msg>                           
<Msg time='***' type='INFO3' code='103019' target='***' methodName='Map.Draw' machine='***' process='5741' thread='24' elapsed='0.00000'>Number of features drawn: 1</Msg>              
<Msg time='***' type='INFO3' code='103001' target='***' methodName='Map.Draw' machine='***' process='5741' thread='24' elapsed='0.01660'>End of layer draw: LAYER0 </Msg>

     我写了一个简单的Java程序从最初的日志文件中读取每个图层的历次绘制时间，用一个Java对象来描述一次图层绘制，这个对象有以下几个属性：String layerName, float executeTime、float symbolizing、float dataAccess、float symbolDrawing,int features。程序执行以后可以生成若干个文件，每个文件记录了一个图层在这次实验过程中的所有操作时间，文件存成csv格式，方便Excel读取。

    这样我就可以给每个图层输出一个图表，表示在这次实验过程中每个步骤的时间变化，如果是由于某个图层绘制引起的响应时间增加，就可以从图表曲线中观察。

    3、在做完所有的图层分析以后，我发现每个图层的绘制时间都是很平稳的曲线，没有任何一个图层有上升的趋势。于是我重新观察了ExportMapImage的过程，发现除了绘制所有图层之外，最后还有一个步骤就是绘制Label。因为动态服务的Label都是实时计算的，需要考虑一些避让等规则。Label绘制完成以后，会有这样一条信息：

<Msg time='***' type='INFO3' code='103017' target='***' methodName='Map.Draw' machine='***' process='5741' thread='24' elapsed='0.99501'>End of labeling phase (labeling and label draw)</Msg> 

   参考第1步的内容，提取信息—>列模式—>Excel，生成绘制label的时间曲线。

    基于以上三个步骤的分析，终于找到原因，是由于Label绘制时间一直在增长引起的响应时间增加。具体原因我们仍在进行更进一步的分析。由于图层比较多，加上要临时写程序分析日志，整个过程花了1天的时间。这个过程对于我们以后进行性能分析帮助非常大，下一步可以考虑通过一些工具的组合把它做成一个流程，提高以后再做同样分析时的效率。