關於Application_End 與 Application_Start事件觸發情況的測試(待續)
測試項目搭建
定義一個簡單的Mvc項目,有如下文件:
(1)
public class Startup { public void Configuration(IAppBuilder app) { app.Run(context => { return Task.Run( async () => { await Task.Delay(600); await context.Response.WriteAsync("Hello, world." + context.Request.Uri); }); }); } }
(2)
public class Global : System.Web.HttpApplication { protected void Application_Start(object sender, EventArgs e) { DebugUtils.Log("Application_Start"); Task.Run(() => { DebugUtils.beginLog($"bugLog.txt"); }); for (long i = 0; i < 10000000000; i++) ; DebugUtils.Log("Application_Start finished"); } protected void Application_End(object sender, EventArgs e) { DebugUtils.Log("Application_End"); for (long i = 0; i < 10000000000; i++) ; DebugUtils.Log("Application_End finished"); } }
(3)
public class DebugUtils { public static ConcurrentQueue<string> queue = new ConcurrentQueue<string>(); public static void beginLog(string fileName) { string dirPath = "G:\\c#\\www\\debugLog\\"; if (!Directory.Exists(dirPath)) Directory.CreateDirectory(dirPath); using (FileStream fs = new FileStream(dirPath + "/" + fileName, FileMode.Append)) { using (StreamWriter sw = new StreamWriter(fs)) { string str; while (true) { if (queue.TryDequeue(out str)) { sw.WriteLine(str); sw.Flush(); } } } } } public static void Log(string str) { queue.Enqueue("[" + DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff") + "]--[" + Thread.CurrentThread.ManagedThreadId + "]--" + str); } }
測試
常規操作
將站點部署到IIS上後,依次進行 修改config, bin文件夾,站點關閉、重啟,回收線程池 操作,日誌裏都有Application_End的觸發日誌。隨後訪問頁面又會有Application_Start的日誌記錄。
高並發
使用工具模擬請求高並發地訪問這個站點
在此期間修改config, 日誌文件中只有Application_End的記錄,卻沒有Application_Start的記錄。
再次修改config,這次只有Application_Start的記錄,卻又沒有end的了。嘗試多次,一直都這樣輪替出現。
雖然上面日誌中的記錄看上去很平常,但是實際情況卻不是這樣。
於是做了如下修改(每次啟動都使用新的日誌文件)
同樣進行了幾次config文件的修改,新的日誌記錄如下
可以看到Application_Start事件並不會等待Application_End執行完畢才觸發。
待解決的疑問:
上面測試中情況
前面使用同一個日誌文件時,日誌只記錄部分,是因為文件被占用嗎,那為什麽會沒有異常。
很規律地交替出現又是什麽情況……項目中遇到的問題
項目中使用log4net記錄日誌 ,配置文件如下:
<?xml version="1.0" encoding="utf-8" ?>
<log4net>
<appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender" >
<file value="App_Data/Logs/Logs.txt" />
<encoding value="utf-8" />
<appendToFile value="true" />
<rollingStyle value="Size" />
<maxSizeRollBackups value="10" />
<maximumFileSize value="10000KB" />
<staticLogFileName value="true" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%-5level %date [%-5.5thread] %-40.40logger - %message%newline" />
</layout>
</appender>
<root>
<appender-ref ref="RollingFileAppender" />
<level value="DEBUG" />
</root>
</log4net>
Application_Start:
protected override void Application_Start(object sender, EventArgs e)
{
Clock.Provider = ClockProviders.Utc;
//Log4Net configuration
AbpBootstrapper.IocManager.IocContainer
.AddFacility<LoggingFacility>(f => f.UseAbpLog4Net()
.WithConfig(Server.MapPath("log4net.config"))
);
base.Application_Start(sender, e);
SingletonDependency<IOnlineUserManager>.Instance.ReloadWhenApplicationStart();
}
在站點發布後,常常會在某次Application_End事件觸發後,日誌不再記錄,而等過段時間後又會有新的日誌出現(Application_Start的日誌為起始)。
如果Application_End事件觸發後,隨之一定會觸發Application_Start,那 SingletonDependency
是否像上面的測試中情況那樣,出現了執行次序的問題,先觸發了Application_Start,而後觸發Application_End,導致讀取緩存的session信息時,相應文件還沒有保存。
修改日誌記錄文件
public class DebugUtils
{
public static DebugUtils Instance = new DebugUtils();
public static ConcurrentQueue<string> queue = new ConcurrentQueue<string>();
public void beginLog(string fileName)
{
string dirPath = "G:\\c#\\www\\debugLog\\";
if (!Directory.Exists(dirPath))
Directory.CreateDirectory(dirPath);
using (FileStream fs = new FileStream(dirPath + "/" + fileName, FileMode.Append))
{
using (StreamWriter sw = new StreamWriter(fs))
{
string str;
while (true)
{
if (queue.TryDequeue(out str))
{
sw.WriteLine(str);
sw.Flush();
}
}
}
}
}
public void Log(string str, string date)
{
queue.Enqueue($"[{ date }]--[{Thread.CurrentThread.ManagedThreadId}]-[{ this.GetHashCode() }]-{str}");
}
}
public class Global : System.Web.HttpApplication
{
protected void Application_Start(object sender, EventArgs e)
{
DebugUtils.Instance.Log("Application_Start", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff"));
Task.Run(() => { DebugUtils.Instance.beginLog($"bugLog{DateTime.Now.ToString("yyyyMMdd-HHmmssfff")}.txt"); });
for (long i = 0; i < 10000000000; i++) ;
DebugUtils.Instance.Log("Application_Start finished", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff"));
}
protected void Application_End(object sender, EventArgs e)
{
DebugUtils.Instance.Log("Application_End", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff"));
for (long i = 0; i < 10000000000; i++) ;
DebugUtils.Instance.Log("Application_End finished", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff"));
}
}
關於Application_End 與 Application_Start事件觸發情況的測試(待續)