ホームページ > 記事 > Java > Java ログレベル、重複記録、ログ損失の問題を理解する

Java ログレベル、重複記録、ログ損失の問題を理解する

coldplay.xixi転載: 2020-12-11 17:26:349538ブラウズ

java 基本チュートリアルこのコラムでは、Java ログレベルなどの問題の解決方法を紹介します

#関連する無料学習の推奨事項:
java基本チュートリアル

1 ログエラーの一般的な原因

1.1 多くのログフレームワークがある

異なるクラスライブラリは異なるログフレームワークを使用する場合があり、互換性は異なります。問題

1.2 構成が複雑でエラーが発生しやすい

##ログ構成ファイルは通常、非常に複雑です。多くの学生は、構成ファイルを他のプロジェクトやオンラインブログから直接コピーすることに慣れていますが、そうではありません。それらを変更する方法を注意深く検討してください。一般的なエラーは、ログの重複、同期ログのパフォーマンス、非同期ログの構成ミスで発生します。

1.3 ログ自体にいくつかの誤解があります

たとえば、ログの内容を取得するコストが考慮されていない、ログレベルが無差別に使用されているなどです。

2 SLF4J

Logback、Log4j、Log4j2、commons-logging、JDK 独自の java.util.logging などはすべて Java システムのログフレームワークであり、実際にはたくさんあります。異なるクラスライブラリでは、異なるロギングフレームワークの使用を選択することもできます。その結果、ログの一元管理が非常に困難になります。

SLF4J (Simple Logging Facade For Java) は、この問題を解決するための統合ログファサード API を提供します

。つまり、図の紫色の部分はニュートラルロギング API

ブリッジ機能を実装し、青色の部分はさまざまなロギングフレームワーク API (緑色の部分) を SLF4J API にブリッジします。このようにして、さまざまなログ API を使用してプログラムでログを記録する場合でも、最終的には SLF4J ファサード API にブリッジできます。
Adaptation 関数 (赤色の部分) は、SLF4J API と実際のログフレームワーク (灰色の部分) のバインディングを実現できます。

log4j-over-slf4j

を使用して SLF4J への Log4j ブリッジングを実装できますが、slf4j-log4j12 を使用して Log4j への SLF4J 適応を実装することもできます。列は描画されますが、それらを同時に使用することはできません。そうしないと、無限ループが発生します。 jclやjulも同様です。図には 4 つの灰色のログ実装フレームワークがありますが、日常業務で最も一般的に使用されているのは Logback と Log4j であり、両方とも同じ人物によって開発されました。 Logback は Log4j の改良版と考えることができ、より推奨されており、基本的には主流です。

Spring Boot のロギングフレームワークも Logback です。では、なぜ Logback パッケージを手動で導入せずに Logback を直接使用できるのでしょうか?

spring-boot-starter モジュールの依存関係

spring-boot-starter-logging

モジュールspring-boot-starter-logging
自動的に導入されるモジュールlogback -classic (SLF4J および Logback ロギングフレームワークを含む) および SLF4J 用のいくつかのアダプター。このうち、log4j-to-slf4j は Log4j2 API を SLF4J にブリッジするために使用され、jul-to-slf4j は java.util.logging API を SLF4J にブリッジするために使用されます。 3 ログの重複記録

ログの重複記録は、ログの閲覧や統計作業に無用な手間をもたらすだけでなく、ディスクやログ収集システムへの負担も増大します。

ロガー設定の継承関係によりログ記録が繰り返されることになる

CONSOLE のアペンダーは、定義された
<logger>
と という 2 つのロガーに同時にマウントされます。 <root>、定義された <logger> は <root> から継承されるため、同じログがロガーを通じて記録され、ルートレコードなので、アプリケーションパッケージの下のログに重複したレコードが存在します。

心の中では、カスタムロガー構成を実装して、アプリケーションのログで DEBUG レベルのログを一時的に有効にできるようにしたいと考えています。実際、アペンダーを繰り返しマウントする必要はありません。

<logger>
: <pre class="brush:php;toolbar:false"><logger name="org.javaedge.time.commonmistakes.logging" level="DEBUG"/></pre> にマウントされているアペンダーを削除するだけです。

をカスタマイズする場合は、さまざまなアペンダーにログ出力する必要があります。 たとえば、

アプリケーションログはファイル app.log に出力されます

他のフレームワークログはコンソールに出力されます
は、

の additivity 属性を false に設定できるため、## の Appender# は#<root> は継承されません。##<h2>LevelFilter の構成が間違っているとログが重複する可能性があります</h2> <ul> <li><p>ログをコンソールに記録する際、ログレコードは異なるレベルに従って 2 つのファイルに記録されます<br><img src="https://img.php.cn/upload/article/000/000/052/627f5fcc448ae824438e604a1b26cad8-5.png" alt=""></p></li> <li><p>実行結果</p></li> <li>## info.log ファイルには、INFO、WARN、ERROR の 3 レベルのログが含まれていますが、これは予期したものではありません<p><br><img src="https://img.php.cn/upload/article/000/000/052/627f5fcc448ae824438e604a1b26cad8-6.png" alt=""></p> </li> <li>error.log には警告レベルとエラーレベルのログが含まれており、ログ収集が繰り返される結果になります<p><img src="https://img.php.cn/upload/article/000/000/052/41ca1a236e0def682612de6fc2bd1d35-7.png" alt=""></p> </li>##事故責任<li> 一部の企業では自動化された ELK を使用していますログを収集するソリューション , ログはコンソールとファイルに同時に出力されます. 開発者はローカルでテストする場合、ファイルに記録されたログを気にする必要はありません. テスト環境や本番環境では、開発者はサーバーへのアクセス権を持っていないため、元のログファイルで繰り返される問題を見つけるのは困難です。 <p><br></p>#ログが繰り返されるのはなぜですか? </li> </ul>ThresholdFilter ソースコード分析<p></p> <h3>ログレベル ≥ 構成レベル </h3> の場合、<ul>NEUTRAL<li> が返され、フィルターチェーン上の次のフィルターの呼び出しが継続されます。 <code> それ以外の場合は、DENY を返し、ログの記録を直接拒否します。

この場合、

ThresholdFilter# を設定します。 ## から

WARN までなので、

WARN および ERROR レベルのログを記録できます。 LevelFilter は、ログレベルを比較し、それに応じて処理するために使用されます。

一致がある場合、

onMatch

で定義された処理メソッドが呼び出されます。デフォルトでは、処理のために次のフィルターに渡されます (デフォルト値は、 AbstractMatcherFilter 基本クラス)

onMismatch で定義された処理メソッドを呼び出します。デフォルトでは、次のフィルター
# にも渡されます。

# と

ThresholdFilter は異なり、
LevelFilter

レベルの構成だけでは実際には機能しません

。 onMatch 属性と onMismatch 属性が構成されていないため、フィルターは失敗し、INFO 以上のレベルのログが記録されます。訂正LevelFilter の onMatch 属性を ACCEPT に設定すると、INFO レベルのログを受信します。onMismatch 属性を DENY に設定すると、INFO レベル以外はログに記録されません。

この方法では、

_info.log

ファイルには INFO レベルのログのみが含まれ、重複したログは存在しません。
4 非同期ログによりパフォーマンスは向上しますか?

ログをファイルに正しく出力する方法がわかったら、ログがシステムパフォーマンスのボトルネックにならないようにする方法を検討する必要があります。これにより、ディスク(メカニカルディスクなど)のIO性能が悪く、ログ容量が大きい場合にログをどのように記録するかという問題を解決できます。次のログ構成を定義します。合計 2 つのアペンダーがあります:

FILE はすべてのログを記録するために使用される FileAppender です;

CONSOLE は時間とともにレコードを記録するために使用される ConsoleAppender ですフラグ付きログ。

大量のログをファイルに出力すると、ログファイルが非常に大きくなり、パフォーマンステストの結果も混在すると、そのログを見つけるのが困難になります。したがって、ここでは EvaluatorFilter を使用してタグに従ってログをフィルタリングし、フィルタリングされたログを個別にコンソールに出力します。この場合、テスト結果を出力するログにはタイムマークが付加されます。

タグと EvaluatorFilter を一緒に使用して、タグでログをフィルタリングします。

テストコード: 指定された数の大きなログを記録します。各ログには 1MB のシミュレートされたデータが含まれます。最後に、時間のマークが付いたメソッドの実行に時間がかかるログが記録されます:
プログラムを実行すると、1,000 件のログと 10,000 件のログ呼び出しの記録にかかる時間が、それぞれ 5.1 秒と 39 秒であることがわかります。

#ファイルログを記録するだけのコードの場合、これには時間がかかりすぎます。

ソースコード分析

FileAppender は OutputStreamAppender を継承します

ログを追加すると、ログは同期ログ記録である OutputStream に直接書き込まれます。

所以日志大量写入才会旷日持久。如何才能实现大量日志写入时，不会过多影响业务逻辑执行耗时而影响吞吐量呢？

AsyncAppender

使用Logback的AsyncAppender

即可实现异步日志记录。AsyncAppender类似装饰模式，在不改变类原有基本功能情况下为其增添新功能。这便可把AsyncAppender附加在其他Appender，将其变为异步。

定义一个异步Appender ASYNCFILE，包装之前的同步文件日志记录的FileAppender，即可实现异步记录日志到文件

记录1000次日志和10000次日志的调用耗时，分别是537毫秒和1019毫秒

异步日志真的如此高性能？并不，因为这并没有记录下所有日志。

AsyncAppender异步日志坑

记录异步日志撑爆内存
记录异步日志出现日志丢失
记录异步日志出现阻塞。

案例

模拟慢日志记录场景：
首先，自定义一个继承自ConsoleAppender的MySlowAppender，作为记录到控制台的输出器，写入日志时休眠1秒。

配置文件中使用AsyncAppender，将MySlowAppender包装为异步日志记录
测试代码
耗时很短但出现日志丢失：要记录1000条日志，最终控制台只能搜索到215条日志，而且日志行号变问号。
原因分析
AsyncAppender提供了一些配置参数，而当前没用对。

源码解析

includeCallerData
默认false：方法行号、方法名等信息不显示
queueSize
控制阻塞队列大小，使用的ArrayBlockingQueue阻塞队列，默认容量256：内存中最多保存256条日志
discardingThreshold
丢弃日志的阈值，为防止队列满后发生阻塞。默认队列剩余容量＜队列长度的20%，就会丢弃TRACE、DEBUG和INFO级日志
neverBlock
控制队列满时，加入的数据是否直接丢弃，不会阻塞等待，默认是false
- 队列满时：offer不阻塞，而put会阻塞
- neverBlock为true时，使用offer

public class AsyncAppender extends AsyncAppenderBase<ILoggingEvent> {
	// 是否收集调用方数据
    boolean includeCallerData = false;
    protected boolean isDiscardable(ILoggingEvent event) {
        Level level = event.getLevel();
        // 丢弃 ≤ INFO级日志
        return level.toInt() <= Level.INFO_INT;
    }
    protected void preprocess(ILoggingEvent eventObject) {
        eventObject.prepareForDeferredProcessing();
        if (includeCallerData)
            eventObject.getCallerData();
    }}public class AsyncAppenderBase<E> extends UnsynchronizedAppenderBase<E> implements AppenderAttachable<E> {

	// 阻塞队列：实现异步日志的核心
    BlockingQueue<E> blockingQueue;
    // 默认队列大小
    public static final int DEFAULT_QUEUE_SIZE = 256;
    int queueSize = DEFAULT_QUEUE_SIZE;
    static final int UNDEFINED = -1;
    int discardingThreshold = UNDEFINED;
    // 当队列满时：加入数据时是否直接丢弃，不会阻塞等待
    boolean neverBlock = false;

    @Override
    public void start() {
       	...
        blockingQueue = new ArrayBlockingQueue<E>(queueSize);
        if (discardingThreshold == UNDEFINED)
        //默认丢弃阈值是队列剩余量低于队列长度的20%，参见isQueueBelowDiscardingThreshold方法
            discardingThreshold = queueSize / 5;
        ...
    }

    @Override
    protected void append(E eventObject) {
        if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) { //判断是否可以丢数据
            return;
        }
        preprocess(eventObject);
        put(eventObject);
    }

    private boolean isQueueBelowDiscardingThreshold() {
        return (blockingQueue.remainingCapacity() < discardingThreshold);
    }

    private void put(E eventObject) {
        if (neverBlock) { //根据neverBlock决定使用不阻塞的offer还是阻塞的put方法
            blockingQueue.offer(eventObject);
        } else {
            putUninterruptibly(eventObject);
        }
    }
    //以阻塞方式添加数据到队列
    private void putUninterruptibly(E eventObject) {
        boolean interrupted = false;
        try {
            while (true) {
                try {
                    blockingQueue.put(eventObject);
                    break;
                } catch (InterruptedException e) {
                    interrupted = true;
                }
            }
        } finally {
            if (interrupted) {
                Thread.currentThread().interrupt();
            }
        }
    }}

默认队列大小256，达到80%后开始丢弃<=INFO级日志后，即可理解日志中为什么只有两百多条INFO日志了。

queueSize 过大

可能导致OOM

queueSize 较小

默认值256就已经算很小了，且discardingThreshold设置为大于0（或为默认值），队列剩余容量少于discardingThreshold的配置就会丢弃<=INFO日志。这里的坑点有两个：

因为discardingThreshold，所以设置queueSize时容易踩坑。
比如本案例最大日志并发1000，即便置queueSize为1000，同样会导致日志丢失
discardingThreshold参数容易有歧义，它不是百分比，而是日志条数。对于总容量10000队列，若希望队列剩余容量少于1000时丢弃，需配置为1000

neverBlock 默认false

意味总可能会出现阻塞。

若discardingThreshold = 0，那么队列满时再有日志写入就会阻塞
若discardingThreshold != 0，也只丢弃≤INFO级日志，出现大量错误日志时，还是会阻塞

queueSize、discardingThreshold和neverBlock三参密不可分，务必按业务需求设置：

若优先绝对性能，设置neverBlock = true，永不阻塞
若优先绝不丢数据，设置discardingThreshold = 0，即使≤INFO级日志也不会丢。但最好把queueSize设置大一点，毕竟默认的queueSize显然太小，太容易阻塞。
若兼顾，可丢弃不重要日志，把queueSize设置大点，再设置合理的discardingThreshold

以上日志配置最常见两个误区

ログ記録自体の誤解を見てみましょう。

ログプレースホルダーを使用すると、ログレベルを決定する必要がなくなります?

SLF4J の {} プレースホルダー構文は、ログが実際に記録されるときにのみ実際のパラメーターを取得するため、次の問題が解決されます。ログデータ取得に関するパフォーマンスの問題。＃＃＃これは正しいです？

DEBUG ログが記録され、記録のみに設定されている場合> =INFO レベルのログ、プログラムも 1 秒かかりますか?

テストする 3 つのメソッド:

最初の 2 つのメソッドは、slowString を呼び出すため、どちらも 1 秒かかります。 2 番目の方法は、プレースホルダーを使用して、slowString を記録する方法です。この方法では、明示的に String を結合せずに Object を渡すことができますが、遅延するだけです (ログが記録されない場合は省略されます)

Log パラメータ object.toString( ) と 文字列の連結 には時間がかかります。

この場合、ログレベルが事前に決定されていない限り、slowString を呼び出す必要があります。

したがって、
{} プレースホルダー を使用しても、パラメーター値の取得が遅れてログデータ取得のパフォーマンスの問題を解決できません。

ログレベルを事前に判断するほか、ラムダ式を通じて遅延パラメータの内容を取得することもできます。ただし、SLF4J の API はまだラムダをサポートしていないため、Log4j2 ログ API を使用し、

Lombok の @Slf4j アノテーション を **@Log4j2** アノテーションに置き換えて、ラムダ式パラメーターのメソッドを提供する必要があります。
## 次のようにデバッグを呼び出します。署名