Lessons on Slow System Speed and Scaling Apps

[RLJB]

This is FYI, re optimising your app, and for those experiencing system slowness:

(also selfishly serves as a reminder to ourselves in the future)

1. many people configure and write data to LoggedInRegularUser as a way of keeping it in context and using it during processes. Beware of potential system slower: we have found that writing large documents to the Reg User BO (eg as a doc attribute) will slow that user down when they do other things, eg running queries, opening forms, even running processes will be significantly slower for that user if they have a 5 mb+ attachment on their reg user form. This is true even if at doc attribute is NOT being used in the later query etc.

Note: this slowness will only affect the one user (not all users), nothing of interest will show in AwareIM logs to indicate problem

2. Using a multi-step process that requires user interaction will write entries to the Execution_Contexts table. If the process involves a form with document attributes and these files are large then the Execution_Contexts table can become large with large BLOBs.

Note: If this occurs the system slows for ALL users undertaking any function of the system (even logging in). It can slow to a point where a crash will occur, if people keep running the processes. Be very careful filling Execution_Contexts with large BLOBs, you can usually configure around this by breaking it into two or more processes.

3. Queries involving large BO's (ie BOs with many instances) can cause system slowness and even crashes, this is especially true where their are a large number of users resulting in the query being run a lot.

Note: this is hard to diagnose as the AwareIM logs will not show anything wrong. We have found turning on MySQL slow query logging useful, but not perfect as this will provide you with the SQL statement only being executed and the query time and timestamp, from here you have to try and ascertain the Aware Query/Process that this relates to (not always simple if you app is large).

Note regarding logging:

All of this raises one important issue we have discovered, the logging currently makes it VERY hard to find these kinds of problems. We have a Linux memory tool called "Top" to measure memory usage, we can track this per second to see memory spikes. We also have user tickets complaining when system slows, and a remote monitoring tool doing some basic up-time monitoring. And we have MySQL logs for slow queries with timestamps.

BUT you can't easily track what a user is doing in your app when one of these issues above occurs.

It would be AWESOME if there was some form of AwareIM logging that simply outputs to a text file:

ServerTimeStamp | BSVName | LoginName | Useraction

where the 'Useraction' in the above is what the user is doing in your app, it would be:

- the form name, process name, button name they clicked
- the process name that was initiated from a user action

basically "what" the user initiated at that time.

If you had this info, you can map your error/issue to the user interaction by timestamp and zero in on the problem immediately. Current logging does not allow this.

[hpl123]

1+ for better logging

[RentProperty]

+100 for better logging / debugging features. Hopefully this will be part and parcel of the V8 E4 application.

Thanks for the breakdown. Will keep looking out for these pitfalls.

[aware_support]

If you direct logging to a file (and you should!) you will see exactly what you are asking for - a timestamp followed by the user action and much more. Besides you can play with the manual logger settings which is in AwareIM/bin/logger.props. Aware IM uses a very popular log4j package and if you look at its documentation you will see all the options available.

[RLJB]

Maybe I'm not using it correctly, but I have tried this a lot, you do get a lot of info in the logs, unfortunately most of it I don't find useful for debugging. It either tells you too much irrelevant data, or it tells you info that is not useful. It doesn't provide you with the user action that is causing the issue. Some examples of not useful and partially useful info are below.

It would be AWESOME if Support could write a small guide on how to use log4j package so we can just get output like:

Timestamp#bsvName#loginname#user interaction description (eg process name, query name, form name, button name)

One line per interaction. Something that just logs WHAT the user is doing, not all the rule outcomes and evaluations.

Also if you set logging to "Full" in the config, you get too much info (examples below), BUT if you set it to "Medium" you don't get enough, you can do create, queries, etc and nothing shows in log. I think you need a setting in between these two.

Examples of Information that is NOT useful:

Case 1:

INFO: InputAdaptor1.Controller has commited 694400 transactions
INFO: OutputAdaptor1.Controller has commited 700300 transactions
INFO: InputAdaptor1.Controller has commited 694500 transactions
INFO: OutputAdaptor1.Controller has commited 700400 transactions
INFO: InputAdaptor1.Controller has commited 694600 transactions
INFO: OutputAdaptor1.Controller has commited 700500 transactions
INFO: InputAdaptor1.Controller has commited 694700 transactions
INFO: OutputAdaptor1.Controller has commited 700600 transactions
INFO: InputAdaptor1.Controller has commited 694800 transactions
INFO: OutputAdaptor1.Controller has commited 700700 transactions
INFO: InputAdaptor1.Controller has commited 694900 transactions
INFO: OutputAdaptor1.Controller has commited 700800 transactions
INFO: InputAdaptor1.Controller has commited 695000 transactions
INFO: OutputAdaptor1.Controller has commited 700900 transactions
INFO: InputAdaptor1.Controller has commited 695100 transactions
INFO: OutputAdaptor1.Controller has commited 701000 transactions
INFO: InputAdaptor1.Controller has commited 695200 transactions
INFO: OutputAdaptor1.Controller has commited 701100 transactions

Case 2:

java.util.zip.DataFormatException: incorrect header check
at java.util.zip.Inflater.inflateBytes(Native Method)
at java.util.zip.Inflater.inflate(Inflater.java:259)
at java.util.zip.Inflater.inflate(Inflater.java:280)
at org.openadaptor.util.compression.ZipUncompress.uncompress(Unknown Source)
at com.bas.shared.data.BinaryResource.unzipResources(Unknown Source)
at com.bas.shared.docengines.HtmlEngineClient.A(Unknown Source)
at com.bas.basserver.iopipes.EmailSink.A(Unknown Source)
at com.bas.basserver.iopipes.EmailSink.A(Unknown Source)
at com.bas.basserver.iopipes.EmailSink.A(Unknown Source)
at com.bas.basserver.iopipes.EmailSink.C(Unknown Source)
at com.bas.basserver.iopipes.EmailSink.A(Unknown Source)
at com.bas.basserver.iopipes.EmailSink$_E.run(Unknown Source)
at java.lang.Thread.run(Thread.java:745)


Example of partial information (but not enough to be useful):

Case 1: No timestamp, no bsv name, no username, no name of query being run:

INFO: InputAdaptor1.Controller has commited 693800 transactions
Unable to find LoggedInRegularUser.InvestmentRange in query FIND Franchisor WHERE EXISTS Industry WHERE ((Industry IN Franchisor.IndustryLINK AND Industry IN LoggedInRegularUser.IndustryLINK) OR LoggedInRegularUser.IndustryLINK IS UNDEFINED) AND (Franchisor.InvestmentRange=LoggedInRegularUser.InvestmentRange OR LoggedInRegularUser.InvestmentRange IS UNDEFINED)

Case 2: no bsv name, no username, no name of process that initiated this error

2017-01-31 14:44:45,368 ERROR -Exception forming notification for e-mail FW: Add postal from Sally Test <[email protected]> duplicate entry: image006.png E-mail will not be processed
java.util.zip.ZipException: duplicate entry: image003.png


Case 3: no username, no process name, no way of knowing how it was user initiated

2017-01-30 22:11:42,852 Reply#34125#ESC#7466ba7948de63dc259da7eebf829604 -16 Finished resuming process 33739
2017-01-30 22:11:42,852 Reply#34125#ESC#7466ba7948de63dc259da7eebf829604 -17
2017-01-30 22:11:42,852 Reply#34125#ESC#7466ba7948de63dc259da7eebf829604 -17
2017-01-30 22:11:42,862 Reply#33739#ESC#7466ba7948de63dc259da7eebf829604 -17
2017-01-30 22:11:42,862 Reply#33739#ESC#7466ba7948de63dc259da7eebf829604 -17
2017-01-30 22:11:42,862 Reply#33739#ESC#7466ba7948de63dc259da7eebf829604 -19 Resuming process 33739
2017-01-30 22:11:43,837 Reply#33739#ESC#7466ba7948de63dc259da7eebf829604 -17
2017-01-30 22:11:43,837 Reply#33739#ESC#7466ba7948de63dc259da7eebf829604 -17
2017-01-30 22:11:43,837 Reply#33739#ESC#7466ba7948de63dc259da7eebf829604 -20 Executing process MessageES_Sync_1 with parameters: MessageES:155646048
2017-01-30 22:11:44,100 Reply#33739#ESC#7466ba7948de63dc259da7eebf829604 -17
2017-01-30 22:11:44,100 Reply#33739#ESC#7466ba7948de63dc259da7eebf829604 -17
2017-01-30 22:11:44,100 Reply#33739#ESC#7466ba7948de63dc259da7eebf829604 -23 Starting execution of rules when creating business object Notes 155646049

Case 4: No timestamp, no bsv name, no username, no understanding of user interaction

INFO: OutputAdaptor1.Controller has commited 1926200 transactions
Unable to find InvoiceLines.ItemCode in query FIND StockItems WHERE StockItems.ItemCode=InvoiceLines.ItemCode
EmailSource: checking e-mail
INFO: InputAdaptor1.Controller has commited 1909400 transactions
EmailSource: checking e-mail

[Jaymer]

+1

[PointsWell]

+1

My server has collapsed and I can't tell when because there are no timestamps to INFO and WARNING messages.

[Jaymer]

Once you have windows (tabs) open for Server Output and Tomcat Output in the control panel,
BE AWARE OF CPU USAGE

Having those tabs open wastes a TON of CPU.
Here's a screen grab of task manager with the EXACT SAME process identified, and you can see the longer and higher drain on the CPU - this is on a MS Azure server.

Screen Shot 2018-03-04 at 5.06.19 PM.png (33.02 KiB) Viewed 15590 times

terms:
slow performance
high cpu

[himanshu]

+1 for the research/analysis
+1 from developer point logging/debugging are very much important for future improvements and troubleshooting.
+1