Writing Logs in Verify Access - Performance Implications

Contents​

• Overview
• Investigation
• Tracing Functions
• Result
• Conclusion

Overview​

Troubleshooting IBM Security Verify Access or Access Manager (ISAM) mapping rules can be difficult sometimes. Something that makes it much easier is having regular trace statements.
When we want to monitor requests, we also add traces so that we can log events and transactions and then analyze the data in tools such as Kibana (Elasticsearch).

But what happens when we have too many trace statements in our mapping rules and the number of customers using the application increases?

Investigation​

While running some performance tests, we found that the response times spiked after a certain load. Using the Dynatrace OneAgent extension, we noticed that during the execution of some transactions, something was being locked, and being locked for a significant time.

Investigating further, we observed that the writes to the trace.log file were being put on hold, or locked, waiting for another trace to finishing writing.

Tracing Functions​

In the mapping rules, we were using the below tracing function which prints messages into the trace.log file located on the runtime.

traceString() trace

// Import required package to mapping rule.
importPackage(java.util.logging);
// Print string to `trace.log` file.
IDMappingExtUtils.traceString("sessionId: " id + " | " + msg);

To see what kind of impact IDMappingExtUtils.traceString() had on the performance of the appliance, we decided to change the tracing function to the below System.out.println() which writes to the messages.log file instead of the trace.log file. After the change was made, we re-ran the same performance test.

println() trace

// Import required class to mapping rule.
importClass(Packages.java.lang.System);
// Print string to `messages.log` file.
System.out.println("sessionId: " id + " | " + msg);

Result​

After re-running the performance test using System.out.println(), we observed that our average response times were halved and we no longer had any locking.

note

The only change that was made to the appliance was how we wrote the trace statements.

Conclusion​

Seeing this result almost made us want to switch to using System.out.println() for everything we had. So what stopped us?

In ISAM 9.0.7 and above, tracing levels were introduced. This allowed us to dynamically control what was being written to the runtime - especially useful when you have high transaction rates. Unfortunately, dynamically changing the trace level in Verify Access is something you can't currently implement using System.out.println().

traceString() trace

// Print string to `trace.log` file.
IDMappingExtUtils.traceString("sessionId: " id + " | " + msg, Level.INFO);

On top of this limitation, we also discovered that you can't write trace statements in mapping rules that are linked to a STS Chain. This was a huge negative for our implementation.

In the end we used a combination of the two. We used the tracing levels to control how much was being written to trace.log and we re-wrote our non-user specific "system messages" to go to messages.log instead.
As a result, we were able to keep the same level of tracing we wanted for the application, and reduced the overhead that IDMappingExtUtils.traceString() brought to the table. We then use Elasticsearch to combine the two log files together to simplify our debugging processes.