Performance Logging in BeanShell: When Less Is Definitely More

Don’t Let Your Logs Slow You Down

Debug logs are like spice: add just enough, and your code is flavorful. Overdo it, and everything burns. 🧯

In IdentityIQ, BeanShell scripts sometimes loop over thousands of identities or accounts—especially during provisioning or aggregation. Logging inside such loops can silently tank performance, and you won’t even know it unless you measure.

The Logging Trap

Let’s say you write this in a loop that runs 10,000 times:

log.debug("User: " + identity.getDisplayName());

Even if DEBUG mode is off, Java still concatenates the string before checking the logger level. That’s like packing your bags and getting dressed, only to find out your trip was canceled. Waste of effort.

The Smart Way

Guard your logs like this:

if (log.isDebugEnabled()) {
    log.debug("User: " + identity.getDisplayName());
}

Now, if DEBUG isn’t enabled, Java skips the string construction altogether. It’s like checking the weather before packing your suitcase. 🌦️

Real-World Analogy

Imagine you own a pizza place. Every time someone orders a pizza, your chef stops to call you and describe the toppings—regardless of whether you’re listening. That’s what unguarded logs do. But if the chef first checks if you’re on the line (i.e., if logging is enabled), the kitchen runs smoother.

Example: Logging Group Names for a User

import sailpoint.object.Identity;
import sailpoint.object.Link;
import java.util.List;
import org.apache.log4j.Logger;

Logger log = Logger.getLogger("sailpoint.services.bshdemo");

Identity identity = context.getObjectByName(Identity.class, "jdoe");

List links = identity.getLinks();
for (Link link : links) {
    if ("Active Directory".equals(link.getApplicationName())) {
        List groups = link.getAttribute("groups");
        if (groups != null && log.isDebugEnabled()) {
            log.debug("Groups for " + identity.getDisplayName() + ": " + groups.toString());
        }
    }
}

This way, if the system isn’t in DEBUG mode, it won’t waste time converting group lists to strings or writing them.

What Not to Do

if (log.isDebugEnabled()) {
    // Only run this if debugging? Bad idea.
    context.saveObject(new Identity());
}

⚠️ Logging levels should never affect program logic. Don’t let your code act differently just because a logger is on or off.

When It Really Matters

If you’re logging expensive objects like full XML dumps, use guards. For example:

if (log.isDebugEnabled()) {
    log.debug("ProvisioningPlan: " + plan.toXml());
}

Calling toXml() on complex objects like ProvisioningPlan can be slow. Wrap it!

Takeaway

• Use isDebugEnabled(), isInfoEnabled(), or isTraceEnabled() in loops or expensive logs.
• Don’t change business logic based on logging state.
• Think of logging like seasoning—more isn’t always better.