C# 监测每个方法的执行次数和占用时间（测试4）

Posted 2022-01-29 guxingy

　　今天也要做这个功能，就百度一下，结果搜索到了自己的文章。一开始还没注意，当看到里面的一个注释的方法时，一开始还以为自己复制错了代码，结果仔细一看网页的文章，我去，原来是自己写的，写的确实不咋地。

把自己的文章的代码复制了下来，稍微改了一下，运行看了一下效果，然后仔细一看，计算的总时间不对，如下图：

上一篇文章的地址：https://www.cnblogs.com/guxingy/p/10142242.html

改了几个地方：

    /// <summary>
    /// 拦截器
    /// </summary>
    public class CallingLogInterceptor : IInterceptor
    
        private DateTime dt  get; set; 
        private TimeSpan ts  get; set; 

        /// <summary>
        /// 方法执行前
        /// </summary>
        /// <param name="invocation"></param>
        private void PreProceed(IInvocation invocation)
        
            dt = DateTime.Now;
        

        /// <summary>
        /// 方法执行后
        /// </summary>
        /// <param name="invocation"></param>
        private void PostProceed(IInvocation invocation)
        
            ts = DateTime.Now - dt;


            Console.WriteLine($"方法名称：invocation.Method.Name" );
            Console.WriteLine($"开始时间：dt.ToString("yyyy-MM-dd HH:mm:ss fff")");
            Console.WriteLine($"结束时间：DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff")");
            Console.WriteLine($"所用时间：ts.TotalSeconds");


            MethodOperationInfo.Add(invocation, ts.TotalMilliseconds);
        

        /// <summary>
        /// 拦截
        /// </summary>
        /// <param name="invocation"></param>
        public void Intercept(IInvocation invocation)
        
            this.PreProceed(invocation);
            invocation.Proceed();//调用
            this.PostProceed(invocation);
        
    

View Code

    /// <summary>
    /// 测试类1
    /// </summary>
    public class Class5_test1
    
        public virtual void test1()
        
            test4();            
            test3();
            test2();
        
        public virtual void test2()
        
            System.Threading.Thread.Sleep(1000);
        
        public virtual void test3()
        
            System.Threading.Thread.Sleep(2000);
        
        public virtual void test4()
        
            System.Threading.Thread.Sleep(3000);
        
    

View Code

    public class MyProxyGenerator
    
        /// <summary>
        /// 创建一个代理对象
        /// </summary>
        /// <typeparam name="T"></typeparam>
        /// <returns></returns>
        public static T CreateProxy<T>() where T : class
        
            ProxyGenerator generator = new ProxyGenerator();//代理
            CallingLogInterceptor interceptor = new CallingLogInterceptor();//定义 拦截器
            T entity = generator.CreateClassProxy<T>(interceptor);
            return entity;
        
    

View Code

    public class Class2
    
        public static void test1()
        
            Class5_test1 entity = MyProxyGenerator.CreateProxy<Class5_test1>();
            entity.test1();
            MethodOperationInfo.ShowContainsDetail();

            Console.Read();
        
    

View Code

 

说明：所有的测试，只是修改了一下Class5_test1 这个类给

测试1

    /// <summary>
    /// 测试类1
    /// </summary>
    public class Class5_test1
    
        public virtual void test1()
                    
            test2();
            test3();
            test4();
        
        public virtual void test2()
        
            System.Threading.Thread.Sleep(1000);
        
        public virtual void test3()
        
            System.Threading.Thread.Sleep(2000);
        
        public virtual void test4()
        
            System.Threading.Thread.Sleep(3000);
        
    

View Code

问题：这里test1调用了test2、test3、test4，那么执行test1所用时间，应该是test2、test3、test4所用时间的总和，正确所用时间至少应该是6秒（1+2+3），结果这里输出的是3秒多，肯定不对。

 

测试2

    /// <summary>
    /// 测试类1
    /// </summary>
    public class Class5_test1
    
        public virtual void test1()
        
            test4();
            test3();            
            test2();
        
        public virtual void test2()
        
            System.Threading.Thread.Sleep(1000);
        
        public virtual void test3()
        
            System.Threading.Thread.Sleep(2000);
        
        public virtual void test4()
        
            System.Threading.Thread.Sleep(3000);
        
    

View Code

问题：这里的test1方法的所用时间是1秒多，更不对了。

 

结论：

　　测试1 和 测试2 的区别，只是在test1里面改变了test2、test3、test4的执行顺序，结果时间却迥然不同，更奇怪的是，test1的所用时间，更是莫名的接近调用的倒数第二个方法。

　　测试1里面，test1的所用时间，很接近test4。

　　测试2里面，test1的所用时间，很接近test2。

　　反正就是所用时间，很接近 方法体里面 最后一个 调用的方法，原因找到了再补充，了解一下动态代理的原理或许就知道了，也获取是自己写错了，估计是第一种可能

 

 

乘着自己好奇，又测试了一下，看下面哦

    /// <summary>
    /// 测试类1
    /// </summary>
    public class Class5_test1
    
        public virtual void test1()
        
            Console.WriteLine("开始执行test1");
            test4();
            test3();            
            test2();
            Console.WriteLine("执行完成test1");
        
        public virtual void test2()
        
            System.Threading.Thread.Sleep(1000);
        
        public virtual void test3()
        
            System.Threading.Thread.Sleep(2000);
        
        public virtual void test4()
        
            System.Threading.Thread.Sleep(3000);
        
    

View Code

主要是是在，test1方法里面添加了方法的执行情况， 输出 开始执行 和 执行完成。