近日服务器经常出现访问缓慢,有时甚至出现503服务不可用问题。

SESSION临时文件

针对该问题的引发原因,首先是基于以前的经验对php的session文件夹进行排查,发现生成的session临时文件有80多万, 针对该问题先对session文件夹过期session进行了清理,同时计划后期用redis来存储session.

应用程序池

原以为,清理完后,不会再出问题,结果仍然会出现有时候间隙性的访问缓慢,由于平台是基于IIS7,在登录windows 后发现访问缓慢时,CPU与内存并未饱和,于是重启了应用程序池,临时的解决问题,但依旧未根治。

系统重启

正好最近系统更新的了补丁,但未重启,于是在凌晨对服务器进行了重启,结果第二天中午仍然有客户反馈访问不了。

PHP错误日志

出现503后,查看了PHP的错误日志,PHP程序执行超时,排序死循环,大体预估可能存在MYSQL慢查询:

[11-Nov-2018 08:59:01] PHP Fatal error:  Maximum execution time of 60 seconds exceeded in xxx.php on line 6
[11-Nov-2018 08:59:01] PHP Fatal error:  Maximum execution time of 60 seconds exceeded in xxx.php on line 6
[11-Nov-2018 08:59:01] PHP Fatal error:  Maximum execution time of 60 seconds exceeded in xxx.php on line 6
[11-Nov-2018 08:59:01] PHP Fatal error:  Maximum execution time of 60 seconds exceeded in xxx.php on line 6

MYSQL慢日志

通过SQL慢日志分析,发现确实存在一条慢日志查询,而且触发机率非常高,几乎几秒一次,没有索引,未做缓存:

select
sum(phone_province='北京') as 北京,
sum(phone_province='天津') as 天津,
sum(phone_province='上海') as 上海,
sum(phone_province='重庆') as 重庆,
sum(phone_province='河北') as 河北,
sum(phone_province='河南') as 河南,
sum(phone_province='云南') as 云南,
sum(phone_province='辽宁') as 辽宁,
sum(phone_province='黑龙江') as 黑龙江,
sum(phone_province='湖南') as 湖南,
sum(phone_province='安徽') as 安徽,
sum(phone_province='山东') as 山东,
sum(phone_province='新疆') as 新疆,
sum(phone_province='江苏') as 江苏,
sum(phone_province='浙江') as 浙江,
sum(phone_province='江西') as 江西,
sum(phone_province='湖北') as 湖北,
sum(phone_province='广西') as 广西,
sum(phone_province='甘肃') as 甘肃,
sum(phone_province='山西') as 山西,
sum(phone_province='内蒙古') as 内蒙古,
sum(phone_province='陕西') as 陕西,
sum(phone_province='吉林') as 吉林,
sum(phone_province='福建') as 福建,
sum(phone_province='贵州') as 贵州,
sum(phone_province='广东') as 广东,
sum(phone_province='青海') as 青海,
sum(phone_province='西藏') as 西藏,
sum(phone_province='四川') as 四川,
sum(phone_province='宁夏') as 宁夏,
sum(phone_province='海南') as 海南,
sum(phone_province='台湾') as 台湾,
sum(phone_province='香港') as 香港,
sum(phone_province='澳门') as 澳门
from `user_xxx` where phone_province != ''

对于这条SQL,感觉非常奇怪,SQL的调用自于平台的信息披露,这应该是冷门页面,除非是有人在恶意采集数据, 我开始怀疑,有人在恶意的进行平台数据挖掘,由于该接口的数据并未要求实时性,将该接口进行缓存处理。

IIS访问日志

对于上面的结果,我开始着手分析IIS的访问日志,我不得不将日志文件转到linux进行分析,先是对日志中访问状态进行了排序:

awk '{a[$9]+=1}END {for(i in a){print a[i]" "i}}' u_ex181109.log|sort -k1 -rn

总访问量PV在用20万左右,500错误的接近3000。

接着对,访问频率最高的URL进行统计

awk '{a[substr($5,0,40)]+=1}END {for(i in a){print a[i]" "i}}' u_ex181111.log|sort -k1 -rn|less

发现注册页访问量大概500左右,但判断手机号码是否存在的接口却调用了50000多次,由于加了阿里的WAF,没有获取到精准的IP访问来源, 暂且没有判定是否存在手机号码恶意探测,和开发人员沟通后,先做注册流程的调整。

IIS连接数

做完了以上工作,原以为不会再有问题,没想到问题还是会发生,于是对IIS的连接数进行监控,

cmd -> perfmon.msc

在监视工具》性能监视器》添加》计数器》Current Connections, 添加完成后,可以在工具栏中的属性进度其它的调整。

当再次发生访问缓慢时,显示当前连接数接近900多,而平时网站能正常访问时,连接数大概在50左右, 因此问题的根本原因应该就是连接数过大。

  1. 打开IIS,找到网站对应的应用程序池,选择高级设置》队列长度,发现默认为100,改为65535。

  2. 调整IIS的appConcurrentRequestLimit设置:

    c:\windows\system32\inetsrv\appcmd.exe set config /section:serverRuntime /appConcurrentRequestLimit:50000
    

    网上很多教程说设置为100000,当我设置完成时,发现报500错误了,于是通过以上命令改回50000才正常,配置文件位于:

    %systemroot%\System32\inetsrv\config\applicationHost.config
    <serverRuntime appConcurrentRequestLimit="50000" />
    

    该文件不能直接修改,如果不能通过以上命令进行修改,可以将该文件复制出来,修改完成后再张贴到原处。

  3. 调整machine.config中的processModel>requestQueueLimit的设置 由原来的默认5000改为100000,该文件在Windows目录下C:\Windows\Microsoft.NET\Framework\v2.0.50727\CONFIG:

    <configuration>
    <system.web>
        <processModel autoConfig="true"/>
         改为
        <processModel requestQueueLimit="100000"/>
    

    改完会立即生效

  4. 修改注册表,调整IIS 7支持的同时TCPIP连接数 由原来的默认5000改为100000。

    reg add HKLM\System\CurrentControlSet\Services\HTTP\Parameteris /v MaxConnections /t REG_DWORD /d 100000 
    

修改完成后,持续监控IIS连接数。

应用程序

通过对IIS的并发调整后,进行AB测试静态文件,并发在1000以上没有出现访问异常,但访问PHP文件时,出现加载缓慢。 再次对日志文件进行分析,对时间段的并发数进行统计:

awk '{a[substr($2,0,5)]+=1}END {for(i in a){print a[i]" "i}}' u_ex181113.log|sort -k1 -rn|less

根据并发高的时间段,去查找对应的访问地址,发现每一次出现并发高的时候,都会出现以下访问连接:

2018-11-13 00:00:21 POST / xxx 120.27.173.40 Mozilla/5.0+(Windows+NT+6.1;+Win64;+x64)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/70.0.3538.77+Safari/537.36 www.example.com 200 0 64
2018-11-13 00:00:22 POST / xxx 121.43.18.19 Mozilla/5.0+(Windows+NT+6.1;+Win64;+x64)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/70.0.3538.77+Safari/537.36 www.example.com 200 0 64
2018-11-13 00:00:22 POST / xxx 121.43.18.19 Mozilla/5.0+(Windows+NT+6.1;+Win64;+x64)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/70.0.3538.77+Safari/537.36 www.example.com 200 0 64