Diagnosing UI Page Performance

Performance problems in the system can have many causes. Regardless of the cause, they will in many cases show up in the User Interface and lead to a bad User experience for the end users.

When there is slowness in the UI, it is important to find out whether only a particular page is slow, or that the whole system is slow. When there is slowness throughout the system, it is not likely that the performance problems are related to any specific UI page.

This section is about the situation that only a specific page has bad performance. In that case, the cause is most likely in the page itself.

An important cause of bad page performance are too many or too slow SQL statements. Those can be easily analyzed, by enabling appropriate logging:

<logger name="org.eclipse.persistence.sql" level="debug" />
<logger name="org.eclipse.persistence.connection" level="ALL" />
<logger name="com.oracle.jheadstart.controller.jsf.lifecycle.JhsPageLifecycle" level="info" />
<logger name="com.oracle.healthinsurance.common.service.ui.security.components.AuthenticationFilter" level="info" />

The latter 2 lines are for logging the current user and the current page name to the log. The first one is for showing all the SQL statements generated.

The eclipse.persistence loggers influence all sessions in the system and have a bad effect on performance. Use it carefully and sparely.

The application log will contain log lines like:

2017-10-05 16:47:55,951 ... ExecuteThread: '8'... INFO c.o.h.common.service.ui.security.components.AuthenticationFilter - User: <username>
2017-10-05 16:48:36,035 ... ExecuteThread: '8'... INFO c.o.j.controller.jsf.lifecycle.JhsPageLifecycle -
Refresh /SearchClaimsTaskFlow/SearchClaimsTable
2017-10-05 16:48:36,410 ... ExecuteThread: '8'... DEBUG org.eclipse.persistence.sql -  ServerSession(527218544) Connection(1452258606) \
<SQL STATEMENT>
2017-10-05 16:48:36,410 ... ExecuteThread: '8'... DEBUG org.eclipse.persistence.sql -  ServerSession(527218544) Connection(1452258606) \
<SQL STATEMENT>

All the lines with the same ExecuteThread are generated as part the page logged in the second line (SearchClaimsTable).

The same thread number will be reused later on for some other user or request. So care must be taken when grouping them together. This grouping can be done easily when considering the time gaps between requests.

In case a Service Request must be logged, please upload the appropriate (part of) the application log files.

Using Database Session History

Using eclipse.persistence loggers in production may not be acceptable. In that case, database features like Active Session History can be used to find slow SQL. This query summarizes all the active SQL in the last minute executed by an Oracle Health Insurance application. When 'sample_count' is high, it means that that SQL was being executed multiple times during the last minute.

select max(sample_time) last_used,
       max(sample_time) - min(sample_time) elapsed,
       count(*) sample_count,
       session_id,
       session_serial#,
       s.sql_text
from V$ACTIVE_SESSION_HISTORY h
join v$sql s on (h.sql_id = s.sql_id)
join dba_users u on (h.user_id = u.user_id)
where h.IS_SQLID_CURRENT="Y"
and sample_time > sysdate - 1/60
and u.USERNAME like "OHI%"
group by h.session_id, h.session_serial#, s.SQL_text
order by 1

Active Session History contains a snapshot of SQL in execution with an interval of a second. So not all SQL will show up there, only the ones that were in execution when a snapshot was taken. Long running SQL (elapsed time > 1 second) will show up however.