我们该怎么结合日志做优化

Posted 天际线_skyline

tags:

篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了我们该怎么结合日志做优化相关的知识,希望对你有一定的参考价值。

1.前言

  在日常工作中,我们常常会遇到随着业务的发展,系统的性能逐渐无法满足业务需求,这个时候就需要系统进行技术改造或者性能调优。技改可能会包括系统的重构甚至重写,功能的重新划分,但是只要是找了性能的瓶颈点,也许只是一些jvm参数或者常量的调优。

2.优化

  为了寻找系统的性能瓶颈点,如果有一套完整图形化的监控系统固然是好事,但是很多情况都可能无法满足这个要求,更多的是通过日志来完成。因此,在合理的地方打印日志尤为重要。

  上周某日下午,一个线上系统开始打印大量错误日志,查看日志发现错误基本为数据库唯一键冲突,通过分析发现日志发现该系统(下面以系统A称呼)的奖励发放功能在上一个奖罚发放还没有完成的情况下,又触发了新的奖励发放调用,奖励发放未半小时触发一次。因为奖励发放逻辑没有做并发同步处理,导致数据落库的时候发生唯一键冲突。因为是离线发放逻辑不考虑实时性,而且当前的数据量可以通过单机多线程并发处理,所以一方面通过redis锁保证同一时间只有一个奖励发放在处理,另一方面通过进行系统优化,尽可能的降低一次奖励发放的耗时。

  系统A的处理逻辑为,系统A会定时收到系统B的调用,一次消息代表一次奖励发放任务,一次任务包含多个司机,需要分别对多个司机进行奖励发放。基本的处理逻辑是系统A在被调用后,获取任务所需基本信息,分批获取相关司机,多线程执行发放任务,每一次submit任务后都会sleep50毫秒,最后通过countdown同步等待异步任务处理完成,在整个任务的开始和结束的时候都会打印日志。为了确认单个任务的耗时,实现了下面的wrapper类

public class MarketingRunnableWrapper implements Runnable {
    private static final ILog logger = LogFactory.getLog("threadLogger");
    //任务名
    private String            taskName;
    //任务创建时间
    private Long              taskCreateTime;
    //日志flag
    private String            flag;
  
   private Runnable runnable;
public MarketingRunnableWrapper(Runnable runnable) { this(runnable, ""); } public MarketingRunnableWrapper(Runnable runnable, String taskName) { this.runnable = runnable;this.taskName = taskName; this.taskCreateTime = System.nanoTime(); this.flag = LogFactory.getFlag(); } @Override public void run() { Long beginTime = System.nanoTime(); try { runnable.run(); } catch (Exception e) { String msg = "task: " + taskName + " run throw exception"; msgLog(msg, e); } finally { String msg = String.format( "task: %s executed, thread name = %s, delay time = %s ms, executing time = %s ms", taskName, Thread.currentThread().getName(), (beginTime - taskCreateTime) / 1000000, (System.nanoTime() - beginTime) / 1000000); msgLog(msg, null); } } private void msgLog(String msg, Exception e) { LogFactory.setFlag(flag); if (e == null) { logger.info(msg); } else { logger.error(msg, e); } LogFactory.removeFlag(); } }

  该wrapper类实现了Runnable接口,打印一次task的执行的等待耗时和执行耗时。

  根据日志打印和程序常量得到如下数据表:

  总耗时 Ttotal(s) 任务数Nt 总耗时 Ttotal/任务数Nt(ms) 任务总耗时Ttt(ms,相加耗时) 平均Taver/最大任务耗时Tmax(ms) 核心Ntcore/最大线程数Ntm 平均Taver/核心Ntcore(ms)
任务奖励(奖励) 126.000 2437 51.72 27344 11.22/43 10/10(公用) 1.1

   

  上述表格中Ttt和Taver、Tmax都是从单线程的角度来说明的

  1. 数据计算
    任务添加等待时长Tw = 50ms
    如果满线程跑的话,平均单个任务执行实际耗时Tstrt = Taver/Ntcore = 1.1ms
    Tw远远大于Tstrt说明,基本只有一个线程在跑,而且还是跑跑停停,没有发挥多线程的优势
  1. 分析
    因为Twt大于Tstrt,说明添加等待限制了线程池的性能
    平均每个任务执行实际耗时Trorign = Ttotal/Nt = 126000/2437 = 51.72ms ~ Tw(这也说明主要花在了等待上面)
  1. 优化方案
    将等待时间Tw修改为5ms
 
  等待时间优化后,数据如下:
  总耗时 Ttotal(s) 任务数Nt

实际平均任务耗时Trtapt

(总耗时 Ttotal/任务数Nt(ms))

Tw 任务总耗时Ttt(ms,相加耗时) 平均Taver/最大任务耗时Tmax(ms) 核心Ntcore/最大线程数Ntm
理论平均任务耗时Tctapt
(平均Taver/核心Ntcore(ms))
任务奖励(奖励) 415.088 36259 11.5 10 1253473
34.56/147
10/10(公用) 3.5 
   
  从上面这个表可以看出Trtapt比Tctapt大,但是与Tw相近,说明现在主要的耗时还是由Tw,任务插入等待决定,所以还有一定的优化空间,但是相比之前的的吞吐量,提高了接近五倍。
  那是否可以去掉插入等待的时间,直接将任务插入到队列中呢。由于为了保证内存空间不会OOM,一般会设置一个相对合理的队列长度,这样的话就是需要保证队列长度足够长,使得任务可以大批量的插入而不会block,或者设置合理的队列满的处理逻辑,而且较大的队列长度存在对内存空间的压力以及fullgc的风险。因此设置一个合理的任务插入等待时间和一个合理的队列长度(不用太大),可以保证相对较高的吞吐量。

以上是关于我们该怎么结合日志做优化的主要内容,如果未能解决你的问题,请参考以下文章

webstorm代码片段的创建

我的Android进阶之旅NDK开发之在C++代码中使用Android Log打印日志,打印出C++的函数耗时以及代码片段耗时详情

scrapy主动退出爬虫的代码片段(python3)

当我从用户获取数据并将其保存到 SQLite 数据库中时,我应该怎么做才能使列表视图在片段中工作

如何优化C ++代码的以下片段 - 卷中的零交叉

Koa 请求日志打点工具