Overview

A simple and lightweight profiling tool. It provides a function to easily measure the processing time in Microflow with a small footprint.

The innovative AutoMode NanoProfiler has been released at version2.0.0 !

Now, You no longer need to add logs or modify your microflows to monitor their performance. After starting AutoMode NanoProfier in AfterStartUp and configuring it a little, you can measure the execution time of all microflows at the individual action level without making any change in your app. Moreover, you can change profile settings of runnning apps and the measurement overhead is minimal.

Additionally, version 2.1.0 now even adds the ability to count and report the number of SQL statements each action executes.

Microflow statistics is now supported in version 2.4.0 !

Since version 2.4.0, you can download Microflow statistics - such as number of executions, elapsed time, and number of SQLs behind microflow - recorded by AutoMode NanoProfiler as a CSV file.

Documentation

Description

NanoProfiler is a module for measuring the elapsed time of any section in your Microflow with a small footprint. It all works on-memory and doesn't use any Mendix Entity, so it's lightweight and fast.

Typical usage scenario

-To detect bottlenecks when tuning Microflow.-To monitor Microflow’s performance during operation.

What is AutoMode and StdMode?

AutoMode is a new mode that performs measurement automatically without adding measurement actions into individual microflows. In contrast, in the previous StdMode, it was necessary to add measurement actions into microflows, but measurement can be performed at any granularity.

AutoMode Getting started guide

Install NanoProfiler:  Install NanoProfiler from Market Place.

Add Configuration Page :  Add 'SNIP_AutoNanoProfilerConfig' to your apps page  to configure your Auto NanoProfiler .

Add to AfterStartUp:  Add ASU_AutoModeNanoProfiler to your App's AfterStartUp to start Auto NanoProfiler and restart app. It's recommend to call ASU_AutoModeNanoProfiler twice to launch two instances named 'SlowMicroflowMonitor' and 'MicroflowInspector'.

Enabling Auto NanoProfiler:  After restart, open Configuration Page and enable 'SlowMicroflowMonitor' with your preferred threshold millis, loglevel=WARNING, TraceActions=NO. Then, You can reconfigure a running Auto NanoProfiler instance by opening Instances Status and clicking Reconfig Request. This should be done for each node in a cluster configuration.

Useing Regexp filters:  Once you have detected a slow microflow using the 'SlowMicroflowMonitor', you can also enable the 'MicroflowInspector' following the same procedure, specify the desired microflow using Rgexp, and set TraceActions to true to obtain the execution time for each actions.

Scrutinize report:  Scrutinize the report that outputted to log in the following format.

### NanoProfiler Report: profileName=MyFirstModule.ACT_MyAction by AutoMode[MicroflowInspector] : totalTicks = 1038 : totalNanos = 139,978,000 : totalSqlCount = 1+0

#### sectionName = [Start]-[Retrieve list of TimeZone from database] : executedCount = 1 : accumulatedNanos = 47,000 : averageNanos = 47,000 : sqlCount = 0+0

#### sectionName = [Retrieve list of TimeZone from database]-[SUB_MySyb] : executedCount = 1 : accumulatedNanos = 8,528,300 : averageNanos = 8,528,300 : sqlCount = 1+0

#### sectionName = [SUB_MySyb]-[Log message (info)] : executedCount = 518 : accumulatedNanos = 64,955,800 : averageNanos = 125,397 : sqlCount = 0+0

#### sectionName = [Log message (info)]-[SUB_MySyb] : executedCount = 517 : accumulatedNanos = 66,361,600 : averageNanos = 128,358 : sqlCount = 0+0

#### sectionName = [Log message (info)]-[End] : executedCount = 1 : accumulatedNanos = 85,300 : averageNanos = 85,300 : sqlCount = 0+0

About SqlCount: In the SqlCount report, "sqlCount = 1+0" indicates 1 select statement and 0 insert/update/delete statements.

This number is based on the number of SQLs executed from all threads during the period. Therefore, in a busy environment, the number of SQLs executed outside the microflow may be mixed in as noise. So, please use it as a reference value. Also, by comparing the results of multiple executions, you can determine the presence of this type of noise.

StdMode Features and limitations

StartNanoProfiler ActionStart the profiler. You can create multiple profilers and use them at the same time. In that case, identify it with the handle returned by this Action.

TickNanoProfiler ActionProfile point name, elapsed time and number of calls.If an empty string (not empty but empty string) is specified as the handle and there is only one profiler started, it will be recorded in that profiler.This Action took only 19 microseconds each time measured with Mendix 8.12.7 on i7-10610U laptop. As a reference, an empty Java Action took 16 microseconds on the same measurement.

LogNanoProfileAsInfo/Debug/Trace ActionOutput profile results to logger as Info/Debug/Trace like below.The total processing time between each point recorded by Tick Action is output to the log. Please note that the unit is nanoseconds. 1,000,000 nanoseconds is 1 millisecond. SectionName is a concatenation of pointName specified in TickAction.

### NanoProfiler Report: profileName=ACT_Sample : totalTicks = 59 : totalNanos = 8,953,800

#### sectionName = Start ACT_Sample-After Logging : executedCount = 1 : accumulatedNanos = 62,600 : averageNanos = 62,600

#### sectionName = After Logging-After Retrieve User : executedCount = 1 : accumulatedNanos = 3,605,700 : averageNanos = 3,605,700

#### sectionName = After Retrieve User-Start Loop Process : executedCount = 1 : accumulatedNanos = 188,700 : averageNanos = 188,700

#### sectionName = Start Loop Process-Enter SUB_Sample : executedCount = 14 : accumulatedNanos = 1,595,100 : averageNanos = 113,935

#### sectionName = Enter SUB_Sample-Leave SUB_Sample : executedCount = 14 : accumulatedNanos = 1,217,300 : averageNanos = 86,950

#### sectionName = Leave SUB_Sample-End Loop Process : executedCount = 14 : accumulatedNanos = 740,800 : averageNanos = 52,914

#### sectionName = End Loop Process-Start Loop Process : executedCount = 13 : accumulatedNanos = 1,481,600 : averageNanos = 113,969

#### sectionName = End Loop Process-END ACT_Sample : executedCount = 1 : accumulatedNanos = 62,000 : averageNanos = 62,000

StopNanoProfiler ActionStop the profiler. This module has a mechanism to automatically release the related internal resource after the reference to Handle returned by StartNanoProfiler Action is lost, but it is usually recommended to explicitly stop and release the resource. 

Dependencies

- There is no dependency on other modules.- About Mendix modeler version, you can see it on Usage section.

Installation

You can download and install the module from the App Store on Studio Pro in the regular way.

Configuration

Add the NanoProfiler action to the Microflow you want to measure by referring to the sample image.

Known bugs

There is no known bugs.