Adding log to CubaApplicationServlet - too long request processing

Hi

I have a “too long request processing” issue to track that happen only in production environment (of course) and I would like to add logs in order to identify the faulty RPC call.

More precisely I have a user who gets stuck sometimes when he logs in, which generates following log output.

15:25:53.487 WARN c.h.c.web.sys.CubaApplicationServlet - Too long request processing [1992841 ms]: ip=10.10.119.110, url=/cpx/UIDL/
15:25:53.488 WARN c.h.c.web.sys.CubaApplicationServlet - Too long request processing [1932814 ms]: ip=10.10.119.110, url=/cpx/UIDL/
15:25:54.495 WARN c.h.c.web.sys.CubaApplicationServlet - Too long request processing [1868793 ms]: ip=10.10.119.110, url=/cpx/UIDL/

It happens randomly, so I tried increasing log output but there is a lot of activity on the server which makes log output cluttered.

So I would like to trace the method invocation that happens on service request (CubaApplicationServet code snippet below).

protected void serviceAppRequest(HttpServletRequest request, HttpServletResponse response)
            throws ServletException, IOException {
        RequestContext.create(request, response);
        statisticsCounter.incWebRequestsCount();

        long startTs = System.currentTimeMillis();

        try {
            super.service(request, response);
        } finally {
            RequestContext.destroy();
        }

        if (hasUidlPathPrefix(request)) {
            long t = System.currentTimeMillis() - startTs;
            if (t > (webConfig.getLogLongRequestsThresholdSec() * 1000)) {
                log.warn(String.format("Too long request processing [%d ms]: ip=%s, url=%s",
                        t, request.getRemoteAddr(), request.getRequestURI()));
            }
        }
    }

I did extend CubaApplicationServlet but I don’t know how to extract meaningful information from the request, e.g the RPC method being invoked in that case, ideally with args.

image

Any help would be appreciated.

Regards
Michael

Hi,
CUBA writes two log files with performance statistics: perfstat.log and perfstat-ui.log. These files are located in the same directory where app.log is located (app_home/logs).
I would start by analyzing these two logs. They will show you which screens are opening slowly, which data loaders load data slowly.

CubaApplicationServlet is too generic. It serves all Vaadin requests, and it’s hard to extract context information in this low level class.

Indeed, logging at servlet level would not be efficient.
I activated perf logs and it does the trick.
Thanks @AlexBudarov
Michael

Hello Michael,

How did you activate perf logs?

BR,
-n

Hi @neutrino

CUBA provides a default logback.xml with the following section.

 <!-- Begin Perf4J  -->

    <!-- To enable performace statistics uncomment the appenders below,
        set loggers level to INFO and uncomment their appender-ref elements -->

    <!--
    <appender name="PerfStatFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${logDir}/app-perfstat.log</file>
        <append>true</append>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>app.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
            <cleanHistoryOnStart>true</cleanHistoryOnStart>
        </rollingPolicy>

        <encoder>
            <pattern>%msg%n</pattern>
        </encoder>
    </appender>

    <appender name="CoalescingStatistics" class="org.perf4j.logback.AsyncCoalescingStatisticsAppender">
        <param name="TimeSlice" value="60000"/>
        <appender-ref ref="PerfStatFile"/>
    </appender>

    <appender name="UIPerfStatFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${logDir}/app-ui-perfstat.log</file>
        <append>true</append>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>app.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
            <cleanHistoryOnStart>true</cleanHistoryOnStart>
        </rollingPolicy>

        <encoder>
            <pattern>%msg%n</pattern>
        </encoder>
    </appender>

    <appender name="UICoalescingStatistics" class="org.perf4j.logback.AsyncCoalescingStatisticsAppender">
        <param name="TimeSlice" value="120000"/>
        <appender-ref ref="UIPerfStatFile"/>
    </appender>
    -->

    <logger name="org.perf4j.TimingLogger" additivity="false" level="OFF">
        <!--<appender-ref ref="CoalescingStatistics"/>-->
    </logger>

    <logger name="com.haulmont.cuba.gui.logging.UIPerformanceLogger" additivity="false" level="OFF">
        <!--<appender-ref ref="UICoalescingStatistics"/>-->
    </logger>

    <!-- End Perf4J  -->

In order to enable perfs logs you have to uncomment it. Beware of the file names in rollingPolicy sections, by default it is the same name than the main log one, which cause name conflict.

I suggest changing this <fileNamePattern>app.%d{yyyy-MM-dd}.log</fileNamePattern>

to this:

<fileNamePattern>app-perfstat.%d{yyyy-MM-dd}.log</fileNamePattern>
<fileNamePattern>app-ui-perfstat.%d{yyyy-MM-dd}.log</fileNamePattern>

Which gives the following

    <appender name="PerfStatFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${logDir}/app-perfstat.log</file>
        <append>true</append>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>app-perfstat.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
            <cleanHistoryOnStart>true</cleanHistoryOnStart>
        </rollingPolicy>

        <encoder>
            <pattern>%msg%n</pattern>
        </encoder>
    </appender>

    <appender name="CoalescingStatistics" class="org.perf4j.logback.AsyncCoalescingStatisticsAppender">
        <param name="TimeSlice" value="60000"/>
        <appender-ref ref="PerfStatFile"/>
    </appender>

    <appender name="UIPerfStatFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${logDir}/app-ui-perfstat.log</file>
        <append>true</append>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>app-ui-perfstat.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
            <cleanHistoryOnStart>true</cleanHistoryOnStart>
        </rollingPolicy>

        <encoder>
            <pattern>%msg%n</pattern>
        </encoder>
    </appender>

    <appender name="UICoalescingStatistics" class="org.perf4j.logback.AsyncCoalescingStatisticsAppender">
        <param name="TimeSlice" value="120000"/>
        <appender-ref ref="UIPerfStatFile"/>
    </appender>

    <logger name="org.perf4j.TimingLogger" additivity="false" level="INFO">
        <appender-ref ref="CoalescingStatistics"/>
    </logger>

    <logger name="com.haulmont.cuba.gui.logging.UIPerformanceLogger" additivity="false" level="INFO">
        <appender-ref ref="UICoalescingStatistics"/>
    </logger>

Regards
Michael

Hi Michael,

To be honest I don’t understand very well what should I change and why?
My problem is that when I open one of my Entity Browser (Transactions), randomly I have: CubaApplicationServlet - too long request processing.
Below my file (I don’t have anything commented - maybe I use another Cuba version):

<appender name="PerfStatFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${logDir}/perfstat.log</file>
    <append>true</append>

    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>${logDir}/perfstat.%d{yyyy-MM-dd}.log</fileNamePattern>
        <maxHistory>30</maxHistory>
        <cleanHistoryOnStart>true</cleanHistoryOnStart>
    </rollingPolicy>

    <encoder>
        <pattern>%msg%n</pattern>
    </encoder>
</appender>

<appender name="CoalescingStatistics" class="org.perf4j.logback.AsyncCoalescingStatisticsAppender">
    <param name="TimeSlice" value="60000"/>
    <appender-ref ref="PerfStatFile"/>
</appender>

<appender name="UIPerfStatFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${logDir}/perfstat-ui.log</file>
    <append>true</append>

    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>${logDir}/perfstat-ui.%d{yyyy-MM-dd}.log</fileNamePattern>
        <maxHistory>30</maxHistory>
        <cleanHistoryOnStart>true</cleanHistoryOnStart>
    </rollingPolicy>

    <encoder>
        <pattern>%msg%n</pattern>
    </encoder>
</appender>

<appender name="UICoalescingStatistics" class="org.perf4j.logback.AsyncCoalescingStatisticsAppender">
    <param name="TimeSlice" value="120000"/>
    <appender-ref ref="UIPerfStatFile"/>
</appender>

<logger name="org.perf4j.TimingLogger" additivity="false" level="INFO">
    <appender-ref ref="CoalescingStatistics"/>
</logger>

<logger name="com.haulmont.cuba.gui.logging.UIPerformanceLogger" additivity="false" level="INFO">
    <appender-ref ref="UICoalescingStatistics"/>
</logger>

<!-- End Perf4J  -->

Best Regards,
-n

Seems that your logback configuration is fine to produce perf stats.

The CubaApplicationServlet - too long request processing message is a general message produced by main CUBA servlet when any request last more than a configurable threshold in Web Config

@Property("cuba.web.logLongRequestsThresholdSec")
@DefaultInt(5)
int getLogLongRequestsThresholdSec();

By enabling perf stat in logback you now have 2 stats files that will help you identifying which requests last the longer. Which will look like below.

image

Now look for calls lasting more than 5000 ms and this is your culprits for the message “too long processing”.

Regards
Michael

Ok Michael,

Let say I identified the culprit but what should I do further? Redo de code or what?
I think is a problem with connection to the database, the program reads (loads) slowly the data.
Also I saw that different browsers give different behaviors.
Could be a RAM problem as well…

Regards,
-n

You could profile your application and especially the slow features.

There are several tools to do that, Java VisualVM is free for instance and generally does the job.

Regards
Michael

Very good information.
Thank you!
-n