===== 背景===== 作为一个程序员或项目负责人,甚至运营人员,很多人都想知道: * 我们的项目访问量怎么样 * 用户访问高峰在什么时候 * 系统变慢的时候用户做了哪些操作 * 用户对哪些功能比较感兴趣 * 真实用户在服务器上的操作轨迹是什么样的 * 系统的瓶颈在哪 * 哪些地方应该优化 * 对什么地方优化可以收益最大化 * 系统是否存在异常访问
却苦于无从获得这些信息。
其实,只要合理记录并仔细分析服务器的访问日志,上面问题都可以找到答案。 ===== 日志格式定义 =====
为了更好的复用分析工具,另外我们也需要记录一些标准日志中没有的信息,因此需要定义用于分析的日志格式。
如果在项目中使用了多种web服务器,只需要根据具体情况定义一种即可。
从性能方便考虑,在apache或nginx上记录日志较好; 从分析的方便程度来说,tomcat或resin更方便一些(因为一般来说,只有动态请求会到达应用服务器,而这些请求也是我们最感兴趣的)。请大家根据自身项目的情况来选择.
==== 基本格式 ====
我们分析的access log格式如下:
执行时间 用户标识(非必需,可以从cookie或session中获得) 远程主机 请求时间 请求url(是否带参数均可) http响应状态 返回字节数
:!: 各种服务器记录执行时间的单位有所不同,tomcat和nginx为毫秒,resin和apache为微秒,这个需要特别注意。
==== apache日志配置 ====
LogFormat "%D %{xxx}C %h %t \"%r\" %>s %b \"%{Referer}i\"" simple CustomLog logs/access_log simple
%D为服务器处理该请求的时间,单位为微秒。
%{xxx}C,从cookie中取名为xxx的cookie值
apache日志格式的说明,请参考 http://httpd.apache.org/docs/2.2/mod/mod_log_config.html#formats
==== nginx日志配置 ====
log_format simple '$request_time $cookie_xxx $remote_addr [$time_local]' '"$request" $status $body_bytes_sent ' '"$http_referer"';
$request_time为服务器处理该请求的时间,单位为毫秒。
$cookie_xxx,从cookie中取名为xxx的cookie值
nginx日志格式的说明,请参考http://wiki.nginx.org/NginxHttpLogModule#log_format
==== tomcat日志配置 ====
<Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs" prefix="localhost_access_log." suffix=".txt" pattern='%D %{xxx}s %h %t "%r" %s %b %{Referer}i' resolveHosts="false"/>
%D为服务器处理该请求的时间,单位为毫秒。
%{xxx}s 从session中取得变量xxx的值
%{xxx}c 从cookie 中取得变量xxx的值
tomcat日志格式的说明,详见http://tomcat.apache.org/tomcat-6.0-doc/config/valve.html#Access%20Log%20Valve
==== resin日志配置 ==== <access-log path-format="logs/access_log.%Y-%m-%d.log" format='%D %{xxx}c %h %t "%r" %s %b "%{Referer}i"' rollover-period="1D"/>
%D为服务器处理该请求的时间,单位为微秒。
%{xxx}c,从cookie中取名为xxx的cookie值
resin日志默认的写法在某些特定情况下会存在严重性能问题,导致所有线程被锁,服务器失去响应。因此请用上面配置完全替换原有配置。resin日志格式的详细说明,请参考http://caucho.com/resin-4.0/admin/logging.xtp#Access%20logging 。
==== 获得多次转发的客户端IP ====
在生产环境中,一般到应用服务器的时候,已经经过了多次转发,如array-->apache(nginx)-->tomcat(resin),这个时候,如果我们想要在access log中获得用户客户端的原始IP,就需要做一些特殊配置。
nginx在进行转发时,一般会设置
proxy_set_header X-Real-IP $remote_addr;
此时,nginx后面的服务器在配置access log时,需要将%h改为%{X-Real-IP}i
array,apache,squid在转发时,一般都会将客户端真实ip放到header中X-Forwarded-For,那么,他们后面的服务器在配置access log时,需要将%h改为%{X-Forwarded-For}i
nginx作为backend server时,跟上面情形有所不同,需要做一些特殊配置:
首先,编译时需要添加一个参数 --with-http_realip_module
然后,需要做如下设置: 设置信任ip列表,也就是负载均衡设备的ip,可以是一个或多个。然后设置保存客户端真实IP的header变量名,一般是X-Real-IP或X-Forwarded-For,如下
set_real_ip_from 192.168.1.0/24; set_real_ip_from 192.168.2.1; real_ip_header X-Real-IP;
===== 概要分析脚本 timeout.awk ===== #对于请求超时的记录进行标记,并打印出来 #!/bin/sh BEGIN{ #基础单位,tomcat/apache为1设为1,resin/nginx/设为1000. base=1 #超时阀值,建议设为300-500,单位为毫秒 valve=500 } #剔除静态文件请求 $7 ~ /\.[jd][hsw][ptr][m]?[l]?[\b\?]?|^\/dwr/ { #总体统计 costTime=$1/base sumTime+=costTime totalCount++ if(min>costTime) min=costTime if(max<costTime) max=costTime
#分布区间 if(costTime>=0 && costTime<1000) {area01+=1} if(costTime>=1000 && costTime<2000) {area12+=1} if(costTime>=2000 && costTime<3000) {area23+=1} if(costTime>=3000 && costTime<4000) {area34+=1} if(costTime>=4000 && costTime<5000) {area45+=1} if(costTime>=5000) {area50+=1}
#超时统计 pos=index($7,"?") if(pos>0) {url=substr($7,0,pos-1)} else { url=$7 }
urlCount[url]++ urlsumTime[url]+=costTime if(costTime>valve) { urlTimeout[url]++ }
} END{ printf("\n当前正在分析文件%s,共处理%s个请求,响应时间最小为%2dms,最大为%8dms,平均%4dms\n",FILENAME,totalCount,min,max,sumTime/totalCount) printf("\n所有请求的分布区间如下:\n") printf("小于1秒的请求%8d个,占%.2f%\n",area01,area01/totalCount*100) printf("1--2秒的请求%8d个,占%.2f%\n",area12,area12/totalCount*100) printf("2--3秒的请求%8d个,占%.2f%\n",area23,area23/totalCount*100) printf("3--4秒的请求%8d个,占%.2f%\n",area34,area34/totalCount*100) printf("4--5秒的请求%8d个,占%.2f%\n",area45,area45/totalCount*100) printf("大于5秒的请求%8d个,占%.2f%\n",area50,area50/totalCount*100) printf("\n下面是请求超时严重的url列表,需要重点优化,当前超时设定为%5dms\n",valve) for(url in urlTimeout) { #超时小于等于3次,或者超时比例20%以下的不输出 if(urlTimeout[url]>3 && (urlTimeout[url]/urlCount[url]>0.2)) { printf("%-80s共处理%5d次,超时%5d次,占%3.2f%,平均耗时%6dms\n",url,urlCount[url],urlTimeout[url],urlTimeout[url]/urlCount[url]*100,urlsumTime[url]/urlCount[url]) } } }
===== 概要分析脚本 timeout.awk ===== 用于生成一个日志分析概览,可以对当前系统的性能有个大概了解,分析结果样式如下:
执行命令
awk -f timeout.awk valve=200 base=1 datafile
其中,valve为超时的阀值,默认500ms,base根据服务器类型,tomcat/apache为1,resin/nginx为1000; 这个脚本仅分析jsp/jhtml/dwr请求,不统计对静态资源的请求。
===== 分析命令 =====
下面在分析核心爆破英语项目时,一些我常用的分析命令,等有时间了再整理为一个工具,也欢迎大家贡献自己的想法。
下面命令仅适用于tomcat和nginx日志,如果是apache或resin日志,请将$1>10替换为$1>10000,这个条件主要用于过滤静态请求。
cost time 10 大 url
awk '$1>10 {print $0}' localhost_access_log.2010-05-21.txt |awk '{print $7}'|awk -F? '{print $1}'|sort|uniq -c|sort -rbg|sed 10q
访问量10大时间点(分钟)
awk '$1>10 {print $0}' localhost_access_log.2010-05-21.txt |awk '{print $4}'|awk -F: '{print $2":"$3}'|sort|uniq -c|sort -rbg|sed 10q
10大ip (访问量最大)
awk '$1>10 {print $0}' localhost_access_log.2010-05-21.txt|awk '{print $3}'|sort|uniq -c|sort -rbg|sed 10q
url时间点分布 (指定URL 访问量 按分钟)
awk '$7~"startLinker.jhtml" {print $0}' localhost_access_log.2010-05-21.txt |awk '{print $4}'|awk -F: '{print $2":"$3}'|uniq -c
指定ip时间点分布 (指定IP 访问量 按分钟)
awk '$1>10 {print $0}' localhost_access_log.2010-05-21.txt |grep '192.168.30.21\b' |awk '{print $4}'|awk -F: '{print $2":"$3}'|uniq -c
指定时间点url分布 (具体某一分钟)
awk '$1>10 {print $0}' localhost_access_log.2010-05-21.txt|grep '12:45'|awk '{print $7}'|awk -F? '{print $1}'|sort|uniq -c|sort -bg
根据用户名查找登录过的ip
awk '{print $2" "$3}' localhost_access_log.2010-05-21.txt |grep 's01o050'|awk '{print $2}'|sort|uniq
|