logback cause performance issue

Question

I have been using logback as log framework and now I got requirement that I need to mask some sensitive data in logs. so I wrote a Encoder like this:

public class MaskLayot extends PatternLayout {
    private String patternsProperty;
    public String getPatternsProperty() {
        return patternsProperty;
    }

    public void setPatternsProperty(String patternsProperty) {
        this.patternsProperty = patternsProperty;
    }
    @Override
    public String doLayout(ILoggingEvent event){
        String message = super.doLayout(event);
        if(patternsProperty != null){
            String[] patterns = patternsProperty.split("|");
            for(int i = 0;i<patterns.length;i++){
                Pattern pattern = Pattern.compile(patterns[i]);
                Matcher matcher = pattern.matcher(message);
                while(matcher.find()){
                    message = matcher.replaceAll("$1$2****$4$5");
                }
            }
        }
        return message;
    }
}

Then I wrote one file appender and one console appender: file appender:

<?xml version="1.0" encoding="UTF-8"?>
<included>
    <appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>
            ${logPath}/${logFile}.log
        </file>
        <rollingPolicy class = "ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>
                ${logPath}/${logFile}-%d.log.gz
            </fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
            <layout class="com.idolice.controller.MaskLayot">
                <patternProperty>
                    (.*)(&lt;dateOfBirth&gt;)(.*?)(&lt;/dateOfBirth&gt;)(.*) | ...etc(many similar patterns)
                </patternProperty>
                <pattern>
                    ${fileLogPattern}
                </pattern>
            </layout>

        </encoder>
    </appender>
    <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
        <queueSize>500</queueSize>
        <discardingThreshold>0</discardingThreshold>
        <appender-ref ref="file"/>
    </appender>
</included>

and the console appender:

<?xml version="1.0" encoding="UTF-8"?>
<included>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
            <layout class="com.idolice.controller.MaskLayot">
                <patternProperty>
                    (.*)(&lt;dateOfBirth&gt;)(.*?)(&lt;/dateOfBirth&gt;)(.*) | ...etc(many similar patterns)
                </patternProperty>
                <pattern>
                    ${consoleLogPattern}
                </pattern>
            </layout>

        </encoder>
    </appender>
</included>

so finally my logback configuration file looks like this:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="default.xml"/>
    <include resource="fileAppender.xml"/>
    <include resource="consoleAppender.xml"/>
    <logger name="com.idolice" level="'INFO"/>
    <logger name="com.idolice" level="'DEBUG"/>
    <root level="info">
        <appender-ref ref="ASYNC"/>
        <appender-ref ref="CONSOLE"/>
    </root>
</configuration>

after I start using the MaskLayout I found that before the request comming it only took 6s to get the response back, but now it will take at least 12s to get the response, so the log configuration must get something wrong, anyone has some experience about this?

Answer 1

One issue that I see there is that you are compiling Patterns for each log event:

            Pattern pattern = Pattern.compile(patterns[i]);

this operation is not cheap and you should do it just once. Maybe in constructor.