Simple business code timeout

Server Code
1

Hi,
I have very simple business logic that

    looks up an entry in a table with little over 100 objects updates the entry if it exists or creates an object otherwhise
The code is run after login (actually after adding or updating an entry to a login sessions table which is done after login). I got a couple of emails before that the business code was interrupted because it took longer than 5 seconds. I find it very strange that this code (which I will add below) would take more than 5 seconds to run but thought there just was a hickup. Today however, our clients are not able to log in. I immediately suspected the business code so I disabled the events and logins started working again. How could the code below cause these issues? 

System.out.println("Adding logon counter for " + session.getUser().getProperty("username") + " - " + session.getAppName() + " - " + session.getSource());


// Current date
Date date = new Date();
DateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd");
String dateStr = dateFormat.format(date);


// Find logon counter for this user, application, source and date
String where = "user.objectId = '" + session.getUser().getObjectId() + "'"
  + " AND appName = '" + session.getAppName() + "'"
  + " AND source = '" + session.getSource() + "'"
  + " AND loginDate = '" + dateStr + "'";


BackendlessDataQuery query = new BackendlessDataQuery();
query.setWhereClause(where);
BackendlessCollection<LogonCounter> queryResult = Backendless.Persistence.of(LogonCounter.class).find(query);


LogonCounter counter;


// Update or create
if(queryResult.getTotalObjects() > 0) {
  counter = queryResult.getData().get(0);
  counter.setCount(counter.getCount() + 1);
} else {
  counter = new LogonCounter();
  counter.setUser(session.getUser());
  counter.setAppName(session.getAppName());
  counter.setSource(session.getSource());
  counter.setLoginDate(dateStr);
  counter.setCount(1);
}


LogonCounter savedCounter = Backendless.Persistence.save(counter);

Our application ID is C6730F91-F429-E4C9-FF61-ED62B2B2E100 and still runs in version 3 of the backend.
Kind regards,
Jeroen Dierckx

2

Hi Jeroen,

You could try to add logging statements to your code to see the exact point where the code hangs. In Backendless Online, there is a small possibility that sometimes business logic is being executed longer than expected (during peak times or server updates etc.), though it shouldn’t happen really often.

Have you tried running the same code in debug mode today? Does it execute longer than expected, too?

3

I will be able to try that later today - we have couple of deliverables that need to be finished first.

The code is not crucial: it is used for login statistics only.

4

I think you might also make this handler async, so that it won’t affect the request in case of failure.

5

I will do that, thanks.

6

FYI: I just received an email that the business logic timed out again. I disabled the logic I was talking about in this thread, but I also have events after login and logout that are still enabled.

the afterLogout method is empty, and the afterLogin method contains only one console log:

System.out.println("User '" + login + "' logged on");

That’s it, nothing else.

I will of course just disable these events, but that definitely should not take 5 seconds, right?

Kind regards,
Jeroen

7

Jeroen,

Have you had a chance to add log statements at the beginning and end of the body of the method? This would give us (and you) the information we need to diagnose it further.

Regards,
Mark

8

I did not yet have the chance to do that, but I will try to do it this evening.

But in the last case, only one line of code is there, which is a log statement - that is the only code that is still active. Should I add a second log statement?

9

Apart from finding out where the issue is: peak time or server updates should not cause the code to timeout, right? Should you not track the time actually spent in the logic?

If a single log statement can take more than 5 seconds, how can I ever trust critical code to live in the business logic?

10

The System.out.println is not really a log statement as in the business logic environment it will not go anywhere. For more information on logging in business logic see the documentation:
https://backendless.com/documentation/business-logic/java/bl_logging.htm

I cannot tell you right now what causes the timeout, that’s why I asked you to help us gather the minimal information which you can get. At this point, we need to confirm that the execution gets in to your event handler (or timer whatever the BL happens to be) and the log statement would certainly assist with that.

11

Additionally: I see you have 5 different event handlers. The one for afterCreate has quite a bit of logic in there. Are you ruling out the possibility that is is that one that caused the email notification about exceeding the 5 second limit?

12

Hi,

I thought you were referring to system logging, I will add proper logging.

I disabled most of the event logic last time (with the check boxes), as I indeed expected the logic you mention to take too long. I explained the logic in this thread. There is some other logic that called an external web service but that code has not been used for a long time.

I will add proper logging and re-enable the code mentioned in the beginning of this thread, while making the code asynchronous to be sure. I will keep the one line of println code after login synchronous and add logging too, as that will probably be simplest to debug when it fails.

Thanks for the swift response.

Kind regards,
Jeroen

13

Hi,

I added the logging and made the two events that contain the actual logic async. All code is active again.

Kind regards,
Jeroen

14

The code has been running for half a day now, and I can see the counters being generated - so the logic is run.

But I can’t find any logging. I used the cache settings from the example (1 message and no delay), and the event handler’s class name as logger name:

LogBuffer.getInstance().setLogReportingPolicy( 1, 0 );
Logger log = Logger.getLogger( LogonSessionsTableEventHandler.class );
log.info(...);

The last log file I can find is from the 31th of March.

Kind regards,
Jeroen

15

Hi Jeroen,

I’ve connected to your application and verified that log file is there. Navigate to Manage > log management, and in the very bottom of the page (in Files section) there is a log file from Apr 25, it contains the logs from the beginning of the April. Currently log file is flushed every time you navigate to log management tab.

Regards Anton

16

Thanks, I can find it now. It seems the logic takes less than half a second in the cases logged so far.

17

That’s good. Are you getting any notifications about the business logic exceeding the 5 seconds limit?

18

So far none. When I do I will of course have a look at the log files. Thanks for the support!

19

I will mark the topic as “Not a problem” for now, and we will definitely revisit it if the problem occurs.

20

Hi,

The timeout occured a couple of times again, the last time about 17 minutes ago.

Kind regards,
Jeroen