High CPU usage on Windows when using loki.source.file on IIS logs

[ceisele-r]

Component(s)

loki.source.file

What's wrong?

When using the following config

loki.source.file "log_scrape_iis" {
 targets = [{
  __address__ = "localhost",
  __path__    = string.format("%s\\inetpub\\logs\\LogFiles\\W3SVC1\\u_ex*.log", sys.env("SystemDrive")),
  instance    = constants.hostname,
  job         = "integrations/iis",
  site        = "Default Web Site",
  },
 ]
 file_match {
  enabled = true
  sync_period = "15m"
 }
 forward_to = [loki.process.logs_integrations_integrations_iis_process.receiver]
}

to scrape IIS log files from the path C:\inetpub\logs\LogFiles\W3SVC1, it causes a high CPU usage for the Alloy process.

Here's the flame graph from the cpu.pprof profile generated using Invoke-WebRequest -Uri "http://localhost:12345/debug/pprof/profile?seconds=30" -OutFile "cpu.pprof":

This is the flame graph from a server where the C:\inetpub\logs\LogFiles\W3SVC1 directory contains ~1.100 logfiles with a filesize of 5-10MB each.

It shows that significant time is spent tailing the files.
It seems that the tailer code calls createFile, GetFileInformationByHandle and CloseHandle indefinitely in a loop for every file causing the high CPU usage.

Steps to reproduce

1. Use a Windows Server with IIS and some traffic (so logs are generated)
2. Add the above loki.source.file module to the Alloy config
3. Start alloy
4. Watch the process CPU usage

System information

Windows Server 2022 Datacenter

Software version

Grafana Alloy v1.16.1

Configuration

loki.source.file "log_scrape_iis" {
 targets = [{
  __address__ = "localhost",
  __path__    = string.format("%s\\inetpub\\logs\\LogFiles\\W3SVC1\\u_ex*.log", sys.env("SystemDrive")),
  instance    = constants.hostname,
  job         = "integrations/iis",
  site        = "Default Web Site",
  },
 ]
 file_match {
  enabled = true
  sync_period = "15m"
 }
 forward_to = [loki.process.logs_integrations_integrations_iis_process.receiver]
}

Logs

Tip

_{React with 👍 if this issue is important to you.}

[kalleep]

Hey, thanks for creating this issue. There are a couple of things you can tweak in the config to make this better.

1. file_watch. This controlls how often alloy will poll for changes to a file
2. Possibly configure ignore_older_than in file_match block depending on how ISS is doing rotations. I would imagine that some of the files in there are rotated file? If so how does these files get rotated and what is the naming scheme for it?

[ceisele-r]

Hi @kalleep thank you for the fast response and the tips.

The naming scheme is 1 file per day - e.g. u_ex260508.log for today, u_ex260507.log for yesterday etc.

Changing the configuration to

loki.source.file "log_scrape_iis" {
 targets = [{
  __address__ = "localhost",
  __path__    = string.format("%s\\inetpub\\logs\\LogFiles\\W3SVC1\\u_ex*.log", sys.env("SystemDrive")),
  instance    = constants.hostname,
  job         = "integrations/iis",
  site        = "Default Web Site",
  },
 ]
 file_watch { // Added
  min_poll_frequency = "15s" // Added
  max_poll_frequency = "1m" // Added
 } // Added
 file_match {
  enabled = true
  sync_period = "15m"
  ignore_older_than = "48h" // Added
 }
 forward_to = [loki.process.logs_integrations_integrations_iis_process.receiver]
}

(ignore files older than 48h - because IIS log files are rotated each day and reducing the poll frequency to be within 15s-1m) massively reduced the CPU usage a lot.

That's great, thanks a lot! 🥳

[kalleep]

Yeah it's a bit annoying having to manually tweak this things. We are looking into having better "task" oriented documentation and other solutions for these kind of things. cc @ptodev @kgeckhart

[kalleep]

Will keep this open for now so that I don't forget to either have documentation for this specific case or what ever other solution we land in.