Hazelcast SlowOperationDetector to identify operations with less than 1 sec execution time

Question

I have a performance use case by which I need to identify certain process() calls in the EntryProcessor which takes more than 300 milliseconds. I tried to make use of SlowOperationDetector with the following configuration.

    <!-- SlowOperation Detector Configuration -->
    <property name="hazelcast.slow.operation.detector.enabled">true</property>
    <property name="hazelcast.slow.operation.detector.stacktrace.logging.enabled">true</property>
    <property name="hazelcast.slow.operation.detector.log.purge.interval.seconds">60000</property>
    <property name="hazelcast.slow.operation.detector.log.retention.seconds">60000</property>
    <property name="hazelcast.slow.operation.detector.threshold.millis">300</property>

I have given a sample test code which sleeps for 1 second inside process().

public static void main(String args[])
{
    Config cfg = null;
    try {
        cfg = new FileSystemXmlConfig("C:\\workarea\\hazelcast\\hazelcast-perf.xml");
    } catch (FileNotFoundException e) {
        // TODO Auto-generated catch block
        e.printStackTrace();
    }

    HazelcastInstance hazelcastInstance = Hazelcast.newHazelcastInstance(cfg);
    IMap<String, Employee> employeesMap = hazelcastInstance.getMap("anyMap");
    employeesMap.put("100", new Employee(100));
    SlowEntryProcessor slowEntryProcessor = new SlowEntryProcessor();
    employeesMap.executeOnKey("100", slowEntryProcessor);

}

static public class SlowEntryProcessor implements EntryProcessor<String, Employee>
{

    private static final long serialVersionUID = 1L;

    @Override
    public EntryBackupProcessor<String, Employee> getBackupProcessor() 
    {
        return null;
    }

    @Override
    public Object process(Entry<String, Employee> arg0) 
    {
        System.out.println("About to sleep");
        try {
            Thread.sleep(1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        System.out.println("done processing");
        return null;
    }

}   

I don't get to see any logs when the configured threshold is less than 1000ms. So in this example, I don't see any slow operation stack trace or logs.

If I change the sleep time to 2 sec, and slow operation threshold to 1 sec, slow operation detector kicks in and logs are displayed.

Is this a bug in SlowOperationDetector or am I missing something here ?

Answer 1

It isn't a bug; but design. What we do is periodically scan the current executing operations. So it depends on the frequency of scanning. The slow operation detector isn't intended to be used (and therefor not designed) to detect such short operations. It is really intended for multi second operation execution.