# logrotate causing 100% CPU usage (but works on Sat) [SOLVED]

## hanj

Hello All

I'm experiencing a problem with only one of my boxes and logrotate. Every morning this box has 100% CPU usage, with logrotate being the out of control process. The weird thing on Saturday, when it's suppose to do it's rotate.. it works fine and doesn't consume full CPU. I'm trying to track down what it's getting hung up on.. but can't.

Here is output of -d -v

```
usr/sbin/logrotate /etc/logrotate.conf -d -v

reading config file /etc/logrotate.conf

including /etc/logrotate.d

reading config file apache2

reading config info for /var/log/apache2/*log 

reading config file emerge

reading config info for /var/log/emerge.log

reading config info for /var/log/cron.log

reading config file hosts

reading config info for /var/log/hosts/*/*log

reading config file mail

reading config info for /var/log/mail.log

reading config file mysql

reading config file net-snmpd

reading config info for /var/log/net-snmpd.log

reading config file syslog-ng

reading config info for /var/log/messages 
```

which leads to:

```
11914 root      25   0  5748 4832  512 R 93.6  0.3   0:50.03 logrotate
```

93.6 is the %CPU.

Here is my logrotate.conf

```
weekly

rotate 4

create

include /etc/logrotate.d

notifempty

nomail

noolddir
```

Contents of /etc/logrotate.d

```
-rw-r--r--  1 root root  221 Jul 30 15:40 apache2

-rw-r--r--  1 root root  106 Jan 30  2005 emerge

-rw-r--r--  1 root root  289 Nov 20  2005 hosts

-rw-r--r--  1 root root   50 Apr  2 10:08 mail

-rw-r--r--  1 root root   55 Apr  2 10:08 net-snmpd

-rw-r--r--  1 root root  352 Aug 30 06:54 syslog-ng
```

emerge:

```
/var/log/emerge.log{

        missingok

        weekly

        nocompress

}

/var/log/cron.log{

        missingok

        weekly

        nocompress

}
```

hosts:

```
/var/log/hosts/*/*log{

        rotate 5

        weekly

        missingok

        sharedscripts

}
```

mail:

```
/var/log/mail.log{

        missingok

        weekly

        compress

}
```

net-snmpd:

```
/var/log/net-snmpd.log{

        missingok

        weekly

        compress

}
```

syslog-ng:

```
/var/log/messages {

        sharedscripts

        weekly

        compress

        postrotate

                /etc/init.d/syslog-ng reload > /dev/null 2>&1 || true

        endscript

}
```

Here are the contents of /etc/cron.daily/logrotate.cron:

```
#! /bin/sh

/usr/sbin/logrotate /etc/logrotate.conf
```

Again the weird thing is that on Saturday, CPU is not pegged, and ALL of my logs get rotated.

```
-rw-------  1 root    root    2495829 Aug 30 07:10 messages

-rw-------  1 root    root     301198 Aug 26 07:12 messages.1.gz

-rw-------  1 root    root     507416 Aug 19 06:51 messages.2.gz

-rw-------  1 root    root     358197 Aug 12 08:12 messages.3.gz

-rw-------  1 root    root     290433 Aug  5 06:33 messages.4.gz

-rw-------  1 root    root         16 Aug 30 03:00 messages.offset

-rw-rw----  1 portage portage    6401 Aug 30 03:13 emerge.log

-rw-rw----  1 portage portage   14660 Aug 26 03:10 emerge.log.1

-rw-rw----  1 portage portage   14044 Aug 19 03:10 emerge.log.2

-rw-rw----  1 portage portage   11000 Aug 12 03:08 emerge.log.3

-rw-rw----  1 portage portage   13607 Aug  5 03:09 emerge.log.4

-rw-------  1 root    root          0 Aug 26 07:12 cron.log

-rw-------  1 root    root          0 Aug 19 06:51 cron.log.1

-rw-------  1 root    root          0 Aug 12 08:11 cron.log.2

-rw-------  1 root    root          0 Aug  5 06:33 cron.log.3

-rw-------  1 root    root          0 Jul 29 06:34 cron.log.4

-rw-------  1 root    root     251307 Aug 30 06:29 mail.log

-rw-------  1 root    root      38867 Aug 26 07:12 mail.log.1.gz

-rw-------  1 root    root      52103 Aug 19 06:51 mail.log.2.gz

-rw-------  1 root    root      53883 Aug 12 08:12 mail.log.3.gz

-rw-------  1 root    root      33864 Aug  5 06:33 mail.log.4.gz

-rw-------  1 root    root         15 Aug 30 03:00 mail.log.offset

-rw-r--r--  1 root    root     158905 Aug 30 07:10 net-snmpd.log

-rw-r--r--  1 root    root         20 Aug 26 07:12 net-snmpd.log.1.gz

-rw-r--r--  1 root    root      13108 Aug 19 06:51 net-snmpd.log.2.gz

-rw-r--r--  1 root    root         20 Aug 12 08:12 net-snmpd.log.3.gz

-rw-r--r--  1 root    root         20 Aug  5 06:33 net-snmpd.log.4.gz

this is a host (/var/log/hosts/*/*log) example

-rw-------  1 root root 2048515 Aug 30 07:13 everything.log

-rw-------  1 root root 3114428 Aug 26 07:12 everything.log.1

-rw-------  1 root root 3079737 Aug 19 06:51 everything.log.2

-rw-------  1 root root 3125827 Aug 12 08:09 everything.log.3

-rw-------  1 root root 3126642 Aug  5 06:29 everything.log.4

-rw-------  1 root root 2963922 Jul 29 06:33 everything.log.5
```

Notice, the last successfull rotate was Aug 26(Sat). So I'm not sure what's going on. Everyday logrotate runs to see if it needs to rotate anything. All my files are rotated on a weekly basis.. and it doesn't need to do anything.. but then freaks on that fact. Is there any way of determining what is going on so I can fix it? Anyone else run into this problem before? Currently this is the only box that is doing this.. and it's been doing it for a while.

Thanks much!

hanjiLast edited by hanj on Wed Nov 19, 2008 5:06 pm; edited 1 time in total

----------

## limn

You might try moving the syslog-ng config file out of the way and see if the problem occurs.

Running strace on the rogue logrotate process may help diagnose.

----------

## hanj

Hello

Sorry to dig this thread back up, but I'm still having problems with this box and thought I would address it again. To do some testing, I moved all the logrotate scripts out to see what was causing the problem. To my surprise the behavior continued even after ALL scripts have been removed. Logrotate will usually run for several hours (approximately 6 hours) before completing and the CPU is pegged at 100% throughout that time.

I ran strace on this, and I seems to be stuck on stating /etc/localtime

```
8776  execve("/usr/sbin/logrotate", ["/usr/sbin/logrotate", "-d", "/etc/logrotate.conf"], [/* 45 vars */]) = 0

8776  brk(0)                            = 0x8054000

8776  access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)

8776  open("/etc/ld.so.cache", O_RDONLY) = 3

8776  fstat64(3, {st_mode=S_IFREG|0644, st_size=117732, ...}) = 0

8776  mmap2(NULL, 117732, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7f1d000

8776  close(3)                          = 0

8776  open("/usr/lib/libpopt.so.0", O_RDONLY) = 3

8776  read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0 \22\0\0004\0\0\0,"..., 512) = 512

8776  fstat64(3, {st_mode=S_IFREG|0755, st_size=43540, ...}) = 0

8776  mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f1c000

8776  mmap2(NULL, 46156, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7f10000

8776  mmap2(0xb7f1b000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xa) = 0xb7f1b000

8776  close(3)                          = 0

8776  open("/lib/libc.so.6", O_RDONLY)  = 3

8776  read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0@a\1\0004\0\0\0\244"..., 512) = 512

8776  fstat64(3, {st_mode=S_IFREG|0755, st_size=1237276, ...}) = 0

8776  mmap2(NULL, 1242576, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7de0000

8776  mmap2(0xb7f0a000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x12a) = 0xb7f0a000

8776  mmap2(0xb7f0d000, 9680, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7f0d000

8776  close(3)                          = 0

8776  mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7ddf000

8776  set_thread_area({entry_number:-1 -> 6, base_addr:0xb7ddf6c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1})

= 0

8776  mprotect(0xb7f0a000, 8192, PROT_READ) = 0

8776  mprotect(0xb7f54000, 4096, PROT_READ) = 0

8776  munmap(0xb7f1d000, 117732)        = 0

8776  brk(0)                            = 0x8054000

8776  brk(0x8075000)                    = 0x8075000

8776  open("/etc/popt", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)

8776  open("/root/.popt", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)

8776  stat64("/etc/logrotate.conf", {st_mode=S_IFREG|0644, st_size=735, ...}) = 0

8776  open("/etc/logrotate.conf", O_RDONLY|O_LARGEFILE) = 3

8776  fstat64(3, {st_mode=S_IFREG|0644, st_size=735, ...}) = 0

8776  _llseek(3, 0, [735], SEEK_END)    = 0

8776  _llseek(3, 0, [0], SEEK_SET)      = 0

8776  read(3, "# $Header: /home/cvsroot/gentoo-x"..., 735) = 735

8776  close(3)                          = 0

8776  write(2, "reading config file /etc/logrotat"..., 40) = 40

8776  write(2, "including /etc/logrotate.d\n"..., 27) = 27

8776  stat64("/etc/logrotate.d", {st_mode=S_IFDIR|0755, st_size=48, ...}) = 0

8776  open(".", O_RDONLY|O_LARGEFILE)   = 3

8776  open("/etc/logrotate.d", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 4

8776  fstat64(4, {st_mode=S_IFDIR|0755, st_size=48, ...}) = 0

8776  fcntl64(4, F_SETFD, FD_CLOEXEC)   = 0

8776  getdents64(4, /* 2 entries */, 4096) = 48

8776  getdents64(4, /* 0 entries */, 4096) = 0

8776  close(4)                          = 0

8776  time(NULL)                        = 1227019409

8776  stat64("/var/lib/logrotate.status", {st_mode=S_IFREG|0644, st_size=18735247, ...}) = 0

8776  open("/var/lib/logrotate.status", O_RDONLY|O_LARGEFILE) = 4

8776  fstat64(4, {st_mode=S_IFREG|0644, st_size=18735247, ...}) = 0

8776  mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f39000

8776  read(4, "logrotate state -- version 2\n\"/va"..., 4096) = 4096

8776  open("/etc/localtime", O_RDONLY)  = 5

8776  fstat64(5, {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  fstat64(5, {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f38000

8776  read(5, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0\0"..., 4096) = 2427

8776  close(5)                          = 0

8776  munmap(0xb7f38000, 4096)          = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0

8776  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2427, ...}) = 0
```

Here is my localtime

```
ls -al /etc/localtime

lrwxrwxrwx 1 root root 31 Apr  3  2005 /etc/localtime -> /usr/share/zoneinfo/US/Mountain

-rw-r--r-- 1 root root 2427 Oct 27 08:20 /usr/share/zoneinfo/US/Mountain
```

Any ideas??

Thanks!

hanji

----------

## hanj

Whoa.. I finally found the solution to this problem. I came across this thread after googling some of the strace output

http://osdir.com/ml/gentoo.hardened/2006-02/msg00031.html

Well, the problem was related to the /var/lib/logrotate.status file. My file was 18MBs. I simply removed that, and bam... everything works as expected! It'll feel good to add 'SOLVED' to this.

Thanks!

hanji

----------

