log4j记录日志问题

wgd81685 2017-02-23 11:03:40

以下是我现在在做项目中的一部分代码，该项目是多线程的，使用log4j记录日志
logger.debug(portName + " recv:len=" + len);
logger.debug(portName + " recv:" + HexUtils.encode(tempBuffer));
以上两句代码记录了从流中读取的数据，查询日志发现，这两句日志之间的时间间隔不稳定，99%的情况下，这两句日志之间几乎无时间间隔，但是在某些时候会出现两句日志的时间间隔相差10秒钟的情况，这种情况非常的不合理，通过仔细分析日志发现，在出现这种特殊情况的时候，记录的日志的时间发生混乱，时间较早的日志在时间较晚的日志之后。

现在因为这个时间间隔的问题而导致项目运行不稳定，请教大神有什么问题会导致这种日志记录混乱的情况的发生！！！！！



                    byte[] buffer = new byte[1024];

                    int len = input.read(buffer);

                    if (len <= 0) {

                        break;

                    }

                    logger.debug(portName + " recv:len=" + len);

                    long start = System.nanoTime();

                    synchronized (recvObj) {

                        for (int i = 0; i < len; i++) {

                            recvQueue.add(buffer[i]);

                        }

                    }

                    long now = System.nanoTime();

                    if (now - start > 100 * 1000000) {

                        logger.debug("加载数据用时超过100毫秒，用时" + (now - start) / 1000000 + "毫秒");

                    }

//                    logger.debug(len + "字节数据加载完成");

                    byte[] tempBuffer = Arrays.copyOfRange(buffer, 0, len);

                    if (logLevel > 1) {

                        logger.debug(portName + " recv:" + HexUtils.encode(tempBuffer));

                    }

...全文

457 11 打赏收藏转发到动态举报

写回复

用AI写文章

11 条回复

切换为时间正序

请发表友善的回复…

发表回复

逗泥丸的平方 2017-02-27

打赏
举报

引用 9 楼 wgd81685 的回复:

在绝大多数的时间里，日志的时间顺序是正常的，只在偶尔的情况下出现时间混乱的情况，大概1%的概率。我的猜想是这样的：电脑上有其他的程序抢占了所有的CPU，导致我的程序抢不到CPU，从而导致日志无法被记录。当我的程序抢回CPU的时候，已经有多个线程的日志在等待记录，这时我的程序开始记录日志，但是因为有多个线程的日志等待记录，各个线程又开始抢占CPU记录日志，此时出现记录时间混乱。是这样么？

你是用的async吗... 那个我不是很了解.. log4j本身是有同步机制的...一个对象的时候,记录只会出现延迟,而不会出现你这种顺序错乱.

wgd81685 2017-02-27

打赏
举报

引用 8 楼 qq_35209952 的回复:

[quote=引用 7 楼 wgd81685 的回复:] [quote=引用 6 楼 qq_35209952 的回复:] [quote=引用 4 楼 wgd81685 的回复:] [quote=引用 2 楼 qq_35209952 的回复:] 这个时间有什么很消耗性能的定时任务吗? 这里是有多少个线程? 有没有打印线程ID... 单一的线程有时间混乱的问题吗?

项目本身并没有什么非常消耗性能的定时任务，但是项目有调用动态库，不知道动态库内部是否有消耗性能的情况项目的线程大概有100多个单一的线程并没有出现时间混乱的问题 [/quote]你所有线程使用的日志对象同是一个吗.[/quote] 部分线程使用的日志对象是同一个[/quote] 你logger对象是static的吧.. 如果有多个地方并发... 要不然就都同用一个........ 不过这样可能会降低性能当然我还是说,线程太多了也没用.. 100多线程又没有100核CPU.. 当然分的多了jvm会自己调度,也不用刻意去管.. 只是说看起来没必要把两个任务来并发执行. 再或者只能是不同的logger分成不同的文件了..[/quote] 在绝大多数的时间里，日志的时间顺序是正常的，只在偶尔的情况下出现时间混乱的情况，大概1%的概率。我的猜想是这样的：电脑上有其他的程序抢占了所有的CPU，导致我的程序抢不到CPU，从而导致日志无法被记录。当我的程序抢回CPU的时候，已经有多个线程的日志在等待记录，这时我的程序开始记录日志，但是因为有多个线程的日志等待记录，各个线程又开始抢占CPU记录日志，此时出现记录时间混乱。是这样么？

逗泥丸的平方 2017-02-27

打赏
举报

引用 7 楼 wgd81685 的回复:

[quote=引用 6 楼 qq_35209952 的回复:] [quote=引用 4 楼 wgd81685 的回复:] [quote=引用 2 楼 qq_35209952 的回复:] 这个时间有什么很消耗性能的定时任务吗? 这里是有多少个线程? 有没有打印线程ID... 单一的线程有时间混乱的问题吗?

wgd81685 2017-02-27