Reason for Scale 1000000 for IIS event.duration

[danielw (dan)]

I'm trying to figure out what is the reason for the scale of 1000000 when using the filebeat module for iis for the duration field. Seems a bit strange when trying to build a dashboard for Reponse Times where every value is multiplicated by 1000000.

[stephenb (Stephen Brown)]

Hi @danielw

Exactly which fields are you looking at.

You can look at the exported fields definitions and see the units here.

Many of the time related fields are in micro or nano seconds to support needed resolution.

Depending on what visualization you are using there are different ways to handle.

Which visualization?

You could also go in the index pattern and edit the default formatting for the field and set it how you prefer.

[danielw (dan)]

Hi Stephen,

thanks for your reply:

The field in question ist the time-taken field from the Windows IIS Log:

This is the part in the Module Pipeline Defintion:

- script:
    lang: painless
    source: ctx.event.duration = Math.round(ctx.temp.duration * params.scale)
    params:
      scale: 1000000
    if: ctx.temp?.duration != null

This field is usualy milliseconds. I can understand that there are steps taken to harmonize time units . I was just a bit curious why it is scaled by such a big factor.

When we start to write and use our custom filebeat-modules we want to use also ecs format as it seems to be an usefull thing worth taking into consideration. So i want to stay as close to default settings as possible.

Currently i'm just playing a bit around and tried to do a simple timebased line chart showing iis time taken -> that was the point where i started looking for as the values did seem a bit high for iis response times

[stephenb (Stephen Brown)]

Just to be clear you are using the IIS module of Filebeat correct?

@danielw
EDITED : Read wrong.... Corrected interesting...

I can just make out what you are graphing is event.duration (note it really helps us if you refer to the exact field name you are looking at)

So if you look at the definition of event.duration here

event.duration

Duration of the event in nanoseconds. If event.start and event.end are known this value should be the difference between the end and start time.

type: long
format: duration

So it looks like it is turned from ms (probably what the `ctx.temp.duration) it is multiplied by 1,000,000 in the pipeline to become nanoseconds.

Hmm but that does not right in your graph because then 5000 nanoseconds would be just 5 microseconds did you already do some scaling in the graph?

Perhaps you should be looking at the actual IIS Fields that you can find here ... huh no response times here so that must be the equivalent.

Just corrected / changed...

[danielw (dan)]

@stephenb

So if you look at the definition of event.duration here

Exactly, it is the time-taken field i'm refering to and i try to use the module "iis" with filebeat. Allthough i have added a grok pattern to the default module to reflect our log settings. I have seen that x-forwarded-for was allready commited to filebeat repository but i wasn't able to find it in the latest 7.12 release

IIS-Log setting:

The Grok Block including my modified pattern:

- grok:
    field: message
    patterns:
    - '%{TIMESTAMP_ISO8601:iis.access.time} (?:-|%{IPORHOST:destination.address}) (?:-|%{WORD:http.request.method})
      (?:-|%{NOTSPACE:url.path}) (?:-|%{NOTSPACE:url.query}) (?:-|%{NUMBER:destination.port:long}) (?:-|%{NOTSPACE:user.name})
      (?:-|%{IPORHOST:source.address}) (?:-|%{NOTSPACE:user_agent.original}) (?:-|%{NOTSPACE:http.request.referrer})
      (?:-|%{NUMBER:http.response.status_code:long}) (?:-|%{NUMBER:iis.access.sub_status:long})
      (?:-|%{NUMBER:iis.access.win32_status:long}) (?:-|%{NUMBER:temp.duration:long})'
    - '%{TIMESTAMP_ISO8601:iis.access.time} (?:-|%{NOTSPACE:iis.access.site_name}) (?:-|%{WORD:http.request.method})
      (?:-|%{NOTSPACE:url.path}) (?:-|%{NOTSPACE:url.query}) (?:-|%{NUMBER:destination.port:long}) (?:-|%{NOTSPACE:user.name})
      (?:-|%{IPORHOST:source.address}) (?:-|%{NOTSPACE:user_agent.original}) (?:-|%{NOTSPACE:iis.access.cookie})
      (?:-|%{NOTSPACE:http.request.referrer}) (?:-|%{NOTSPACE:destination.domain}) (?:-|%{NUMBER:http.response.status_code:long})
      (?:-|%{NUMBER:iis.access.sub_status:long}) (?:-|%{NUMBER:iis.access.win32_status:long})
      (?:-|%{NUMBER:http.response.body.bytes:long}) (?:-|%{NUMBER:http.request.body.bytes:long})
      (?:-|%{NUMBER:temp.duration:long})'
    - '%{TIMESTAMP_ISO8601:iis.access.time} (?:-|%{NOTSPACE:iis.access.site_name}) (?:-|%{NOTSPACE:iis.access.server_name})
      (?:-|%{IPORHOST:destination.address}) (?:-|%{WORD:http.request.method}) (?:-|%{NOTSPACE:url.path})
      (?:-|%{NOTSPACE:url.query}) (?:-|%{NUMBER:destination.port:long}) (?:-|%{NOTSPACE:user.name})
      (?:-|%{IPORHOST:source.address}) (?:-|HTTP/%{NUMBER:http.version}) (?:-|%{NOTSPACE:user_agent.original})
      (?:-|%{NOTSPACE:iis.access.cookie}) (?:-|%{NOTSPACE:http.request.referrer}) (?:-|%{NOTSPACE:destination.domain})
      (?:-|%{NUMBER:http.response.status_code:long}) (?:-|%{NUMBER:iis.access.sub_status:long})
      (?:-|%{NUMBER:iis.access.win32_status:long}) (?:-|%{NUMBER:http.response.body.bytes:long})
      (?:-|%{NUMBER:http.request.body.bytes:long}) (?:-|%{NUMBER:temp.duration:long})'
    - '%{TIMESTAMP_ISO8601:iis.access.time} \[%{IPORHOST:destination.address}\]\(http://%{IPORHOST:destination.address}\)
      (?:-|%{WORD:http.request.method}) (?:-|%{NOTSPACE:url.path}) (?:-|%{NOTSPACE:url.query}) (?:-|%{NUMBER:destination.port:long})
      (?:-|%{NOTSPACE:user.name}) \[%{IPORHOST:source.address}\]\(http://%{IPORHOST:source.address}\)
      (?:-|%{NOTSPACE:user_agent.original}) (?:-|%{NUMBER:http.response.status_code:long}) (?:-|%{NUMBER:iis.access.sub_status:long})
      (?:-|%{NUMBER:iis.access.win32_status:long}) (?:-|%{NUMBER:temp.duration:long})'
    - '%{TIMESTAMP_ISO8601:iis.access.time} (?:-|%{IPORHOST:destination.address}) (?:-|%{WORD:http.request.method})
      (?:-|%{NOTSPACE:url.path}) (?:-|%{NOTSPACE:url.query}) (?:-|%{NUMBER:destination.port:long}) (?:-|%{NOTSPACE:user.name})
      (?:-|%{IPORHOST:source.address}) (?:-|%{NOTSPACE:user_agent.original}) (?:-|%{NUMBER:http.response.status_code:long})
      (?:-|%{NUMBER:iis.access.sub_status:long}) (?:-|%{NUMBER:iis.access.win32_status:long})
      (?:-|%{NUMBER:temp.duration:long})'
    - '%{TIMESTAMP_ISO8601:iis.access.time} (?:-|%{NOTSPACE:iis.access.site_name}) (?:-|%{NOTSPACE:iis.access.server_name})
      (?:-|%{IPORHOST:destination.address}) (?:-|%{WORD:http.request.method}) (?:-|%{NOTSPACE:url.path}) (?:-|%{NOTSPACE:url.query})
      (?:-|%{NUMBER:destination.port:long}) (?:-|%{NOTSPACE:user.name}) (?:-|%{IPORHOST:source.address}) (?:-|%{NOTSPACE:user_agent.original})
      (?:-|%{NOTSPACE:http.request.referrer}) (?:-|%{NUMBER:http.response.status_code:long}) (?:-|%{NUMBER:iis.access.sub_status:long})
      (?:-|%{NUMBER:iis.access.win32_status:long}) (?:-|%{NUMBER:http.response.body.bytes:long}) (?:-|%{NUMBER:http.request.body.bytes:long})
      (?:-|%{NUMBER:temp.duration:long}) (?:-|%{IPORHOST:network.forwarded_ip})'
    ignore_missing: true

i did see that the "time-taken" field was parsed with the pattern (?:-|%{NUMBER:temp.duration:long})
and later gets modified and written into event.duration

- script:
    lang: painless
    source: ctx.event.duration = Math.round(ctx.temp.duration * params.scale)
    params:
      scale: 1000000
    if: ctx.temp?.duration != null

the event.duration description fits the description of time-taken quite well, sort of

The time-taken field measures the length of time that it takes for a request to be processed. The client-request time stamp is initialized when HTTP.sys receives the first byte of the request.

so i thought thats ok. but it seems that i havent read the part of the event.duration description, the one with "nanoseconds"

Now it makes sense to me, at least some, as all entries for event.duration will get translated to nanoseconds. I will try to keep this in mind when creating a visualisation of the data.

Duration of the event in nanoseconds. If event.start and event.end are known this value should be the difference between the end and start time.

Thank you very much, the link to the event.duration description realy helped.
Now i have to find out how to get the displayed valued back to ms in the visualisation.

best regards
Dan

[stephenb (Stephen Brown)]

Great Job Digging In! I learned something too!
I edited the title in case anyone looking / searching in the future.

[stephenb (Stephen Brown)]

@danielw depending what visualization you use you can adjust that.

In TSVB you can do this.... (this is an example where the data is in us)

Then in the options you can do this... you might want to give it a try....