关于Application_End 与 Application_Start事件触发情况的测试(待续)

枕上从妨一夜睡,灯前读尽十年诗。这篇文章主要讲述关于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的了。尝试多次,一直都这样轮替出现。
关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

虽然上面日志中的记录看上去很平常,但是实际情况却不是这样。
于是做了如下修改(每次启动都使用新的日志文件)
关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

同样进行了几次config文件的修改,新的日志记录如下
关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

可以看到Application_Start事件并不会等待Application_End执行完毕才触发。
待解决的疑问:
  1. 上面测试中情况
    前面使用同一个日志文件时,日志只记录部分,甚至很规律地交替出现,是因为文件被占用吗?
在打开日志文件时刻意抛出异常,网站可以照常访问,但不再记录日志了,所以文件占用异常确实可以导致上述情况。
publicvoid beginLog(string fileName) { string dirPath = "G:\\\\c#\\\\www\\\\debugLog\\\\"; if (!Directory.Exists(dirPath)) Directory.CreateDirectory(dirPath); throw new Exception("test"); 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(); } }} } }

修改日志记录类为非静态类(1)
public class DebugUtils { public static DebugUtils Instance = new DebugUtils(); public static ConcurrentQueue< string> queue = new ConcurrentQueue< string> (); publicvoid 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(); } }} } }publicvoid Log(string str, string date) { queue.Enqueue($"[{ date }]--[{Thread.CurrentThread.ManagedThreadId}]-[{ this.GetHashCode() }]-{str}"); } }

(2)
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")); } }

快速地修改了3次config(空格,保存,空格,保存,空格,保存), 发现日志文件的创建要滞后许多。
关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

重试了一遍,这次也是3次修改,只触发了两次Application_End
关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

在连续修改config的情况下,start事件几乎是立即就触发了,但end事件如果尚有前一个end事件未执行完成,新的end事件会延后触发。
在end事件中增加代码记录end的触发原因
try { HttpRuntime runtime = (HttpRuntime)typeof(HttpRuntime).InvokeMember("_theRuntime", BindingFlags.NonPublic | BindingFlags.Static | BindingFlags.GetField, null, null, null); if (runtime == null) return; string shutDownMessage = (string)runtime.GetType().InvokeMember("_shutDownMessage", BindingFlags.NonPublic | BindingFlags.Instance | BindingFlags.GetField, null, runtime, null); string shutDownStack = (string)runtime.GetType().InvokeMember("_shutDownStack", BindingFlags.NonPublic | BindingFlags.Instance | BindingFlags.GetField, null, runtime, null); DebugUtils.Instance.Log("MvcApplicationEnd事件触发:" + shutDownMessage + shutDownStack, DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff")); } catch (Exception ex) { DebugUtils.Instance.Log("MvcApplicationEnd事件触发异常:" + ex.Message, DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff")); }

关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

此时的网站日志文件中:
关于Application_End 与 Application_Start事件触发情况的测试(待续)

文章图片

两个明显的请求处理停顿,刚好分别对应了上面的两次start事件
项目中遇到的问题项目中使用log4net记录日志 ,配置文件如下:
< ?xml version="1.0" encoding="utf-8" ?> < log4net> < appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender" > < file value="https://www.songbingjia.com/android/App_Data/Logs/Logs.txt" /> < encoding value="https://www.songbingjia.com/android/utf-8" /> < appendToFile value="https://www.songbingjia.com/android/true" /> < rollingStyle value="https://www.songbingjia.com/android/Size" /> < maxSizeRollBackups value="https://www.songbingjia.com/android/10" /> < maximumFileSize value="https://www.songbingjia.com/android/10000KB" /> < staticLogFileName value="https://www.songbingjia.com/android/true" /> < layout type="log4net.Layout.PatternLayout"> < conversionPattern value="https://www.songbingjia.com/android/%-5level %date [%-5.5thread] %-40.40logger - %message%newline" /> < /layout> < /appender> < root> < appender-ref ref="RollingFileAppender" /> < level value="https://www.songbingjia.com/android/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的日志为起始)。
确实也是因为文件被占用。
解决log4net独占日志文件的问题以及 log4net的各种输出配置
http://logging.apache.org/log4net/release/config-examples.html
log4net系列(三)--详解RollingFileAppender
log4net的配置详解
Application_Start 中的 SingletonDependency< IOnlineUserManager> .Instance.ReloadWhenApplicationStart(); 这行代码为什么经常不生效。
【关于Application_End 与 Application_Start事件触发情况的测试(待续)】因为有socket连接及轮询请求的存在,常常是start事件在end之前被触发,所以在end事件触发时保存用户session数据就不合适了,因为保存与读取 的执行顺序无法保障。

    推荐阅读