SessionRepositoryFilter's getRequestedSession is called unnecessarily.

[hosoitk]

When Spring Session used in the application was upgraded from 1.3.1.RELEASE to 2.1.3.RELEASE, performance was verified and it was confirmed that the CPU utilization has increased by about 10%. When profiling was performed using the function -agentlib: hprof = cpu = samples, it was confirmed that the execution time of RedisOperationsSessionRepository.getSession (String, boolean) has increased after version upgrade.

The increase in the number of executions of RedisOperationsSessionRepository.getSession (String, boolean) is due to the following two updates.

Update point 1

After Spring Session 1.3.4.RELEASE, with implementation of SessionCommittingRequestDispatcher which introduced the change that when screen transition is made to a JSP page containing jsp: include, commitSession is executed each time jsp: include is executed.

Update point 2

getRequestedSessionId has been modified since Spring Session 2.0.0.RELEASE, getRequestedSessionId has been changed to check whether the session ID obtained from cookie by RedisOperationsSessionRepository.findById exists in the session.

commitSession calls getRequestedSessionId, getRequestedSessionId calls RedisOperationsSessionRepository.findById via getRequestedSession. Because RedisOperationsSessionRepository.findById has become is a process that calls RedisOperationsSessionRepository.getSession(String, boolean), increase in the number of executions of commitSession leads to an increase of RedisOperationsSessionRepository.getSession (String, boolean)

This is getRequestedSessionId but due to the modification from Spring Session 2.1.1.RELEASE onwards, getRequestedSession can be executed to update requestedSessionId only when requestedSessionId is null, by caching the requestedSessionId.

However, at the same time in clearRequestedSessionCache a process is added to assign null to requestedSessionId as well and in commitSession in order to execute clearRequestedSessionCache before executing requestedSessionId it has become necessary to execute getRequestedSession.

https://github.com/spring-projects/spring-session/blob/c5fc4b57ad2eb369564927e4fd13850c0f5a94f2/spring-session-core/src/main/java/org/springframework/session/web/http/SessionRepositoryFilter.java#L357-L363

https://github.com/spring-projects/spring-session/blob/c5fc4b57ad2eb369564927e4fd13850c0f5a94f2/spring-session-core/src/main/java/org/springframework/session/web/http/SessionRepositoryFilter.java#L392-L396

https://github.com/spring-projects/spring-session/blob/c5fc4b57ad2eb369564927e4fd13850c0f5a94f2/spring-session-core/src/main/java/org/springframework/session/web/http/SessionRepositoryFilter.java#L229-L248

Since requestedSessionId is not changed during the request, it is better not to clear it

If the call of getRequestedSession is properly controlled from getRequestedSessionId, even if getRequestedSessionId is called from commitSession by SessionCommittingRequestDispatcher.include (ServletRequest, ServletResponse) the behavior of executing RedisOperationsSessionRepository.findById every time will not occur . It is likely that the number of RedisOperationsSessionRepository.getSession (String, boolean) execution will be the same as before the version upgrade.

[oxc]

I can confirm that this leads to the session being loaded from redis multiple times per request, which really should be avoided.

[theigl]

Could somebody take a look at this? The fix suggested by @oxc is quite trivial and prevents hitting Redis multiple times per request.

[sadraskol]

We tried to solve this issue as suggested by @oxc, but it does not positively solve the issue. When including multiple jsp in the same call, the first include does not call redis but subsequent include do.

If i understand the introduction of this feature on its commit commitSession is called to disallow writes on header after an include. Yet, I don't quite get why commitSession is used. As multiple includes can happen in the same request, clearRequestedSessionCache will clear the cache for subsequent includes. I think something like the following should suffice to write only once the header:

@Override
public void include(ServletRequest request, ServletResponse response) throws ServletException, IOException {
    if (!SessionRepositoryRequestWrapper.this.responseHeaderWritten) {
        SessionRepositoryRequestWrapper.this.commitSession();
        SessionRepositoryRequestWrapper.this.responseHeaderWritten = true;
    }
    this.delegate.include(request, response);
}

We are handling large jsp, we have to use jsp:include to be able to compile our jsp. As a result, spring-session pretty much DDOSing our redis instances. @vpavic I see you are busy with #1732 which is related but is there a way to avoid this problem? Did I miss something? Is there a way to help you solve the issue?

[rwinch]

@sadraskol Thanks for the detailed analysis. If you could put together a simplified sample that illustrates the problem that would be the first step. The sample is to make it easier for the team to understand the issue in context.

It sounds like you have a proposal for a solution too. The second step would be putting together a solution. Your sample will demonstrate that the issue is fixed. The someone from the team can iterate on your PR.

[sadraskol]

Thanks @rwinch for the proposal, I create the simplest example I could come up with: https://github.com/sadraskol/spring-session-jsp

I am opening a PR next, overall I feel like the problem is that commitSession should not be called twice in the same request

[rwinch]

It seems like this is the change that added the invalidation 6d027900ee3a1567a5bd95c028b2be16ea503a2c

I'm not exactly sure all the history here. What are your thoughts @vpavic

[sadraskol]

Hello! I think we're all expecting the feedback of @vpavic since quite some time. Is there a way to move the issue forward?

[vpavic]

Sorry for my late follow-up on this.

The history behind the caching of the fetched session in SessionRepositoryFilter has been discussed recently in another PR - see #1732 and specifically in this comment.

In this specific case, I do see the problem as quite a serious one performance-wise, because as you explained @sadraskol the data store gets hit quite a lot. I'll do my best to review your PR by the end of this week.

[lnxmad]

Any update on this?

[pbartoszek]

Any update guys?

As a prove it's still the issue in Spring Session 2.6.1 I attached the sql queries executed for a single request.... Not great performance with two extra select statements...

2022-03-07 12:01:00.645 DEBUG 8896 --- [nio-8080-exec-3] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [SELECT S.PRIMARY_ID, S.SESSION_ID, S.CREATION_TIME, S.LAST_ACCESS_TIME, S.MAX_INACTIVE_INTERVAL, SA.ATTRIBUTE_NAME, SA.ATTRIBUTE_BYTES FROM SPRING_SESSION S LEFT JOIN SPRING_SESSION_ATTRIBUTES SA ON S.PRIMARY_ID = SA.SESSION_PRIMARY_ID WHERE S.SESSION_ID = ?]
2022-03-07 12:01:05.553 DEBUG 8896 --- [nio-8080-exec-3] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL update
2022-03-07 12:01:05.553 DEBUG 8896 --- [nio-8080-exec-3] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [UPDATE SPRING_SESSION SET SESSION_ID = ?, LAST_ACCESS_TIME = ?, MAX_INACTIVE_INTERVAL = ?, EXPIRY_TIME = ?, PRINCIPAL_NAME = ? WHERE PRIMARY_ID = ?]
2022-03-07 12:01:08.755 DEBUG 8896 --- [nio-8080-exec-3] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL query
2022-03-07 12:01:08.755 DEBUG 8896 --- [nio-8080-exec-3] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [SELECT S.PRIMARY_ID, S.SESSION_ID, S.CREATION_TIME, S.LAST_ACCESS_TIME, S.MAX_INACTIVE_INTERVAL, SA.ATTRIBUTE_NAME, SA.ATTRIBUTE_BYTES FROM SPRING_SESSION S LEFT JOIN SPRING_SESSION_ATTRIBUTES SA ON S.PRIMARY_ID = SA.SESSION_PRIMARY_ID WHERE S.SESSION_ID = ?]
2022-03-07 12:01:19.521 DEBUG 8896 --- [nio-8080-exec-3] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL query
2022-03-07 12:01:19.521 DEBUG 8896 --- [nio-8080-exec-3] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [SELECT S.PRIMARY_ID, S.SESSION_ID, S.CREATION_TIME, S.LAST_ACCESS_TIME, S.MAX_INACTIVE_INTERVAL, SA.ATTRIBUTE_NAME, SA.ATTRIBUTE_BYTES FROM SPRING_SESSION S LEFT JOIN SPRING_SESSION_ATTRIBUTES SA ON S.PRIMARY_ID = SA.SESSION_PRIMARY_ID WHERE S.SESSION_ID = ?]

I noticed that SessionRepositoryFilter.commitSession is called twice

1. When request output stream is flushed
2. Then by SessionRepositoryFilter itself via code

   try {
           filterChain.doFilter(wrappedRequest, wrappedResponse);
       }
       finally {
           wrappedRequest.commitSession();
       }

   Is this expected @vpavic ?