Keep Server Online
If you find the Apache Lounge, the downloads and overall help useful, please express your satisfaction with a donation.
or
A donation makes a contribution towards the costs, the time and effort that's going in this site and building.
Thank You! Steffen
Your donations will help to keep this site alive and well, and continuing building binaries. Apache Lounge is not sponsored.
| |
|
 Topic: rotatelogs.exe -p option causing CPU spike |
|
| Author |
|
rguilbault
Joined: 25 Jul 2015
Posts: 7
Location: USA
|
 Posted: Wed 12 Aug '15 18:23 Post subject: rotatelogs.exe -p option causing CPU spike |
 |
|
I recently spent some time trying to cleanup how we're recommending configuration of apache in terms of logfiles (for the purposes of writing parsers/analyzers, etc). one of the items undertaken was causing maintenance of the logfiles (as they'll be more verbose), which I opted to use the -p option to launch a process to archive the older files.
here's my config:
| Code: |
ErrorLog "|bin/rotatelogs.exe -p maint/MaintainLogs.bat -l logs/error.%Y%m%d.log 86400"
CustomLog "|bin/rotatelogs.exe -p maint/MaintainLogs.bat -l logs/access.%Y%m%d.log 86400" access
|
on my Windows 8.1 laptop, rotatelogs is happy and my .bat file is invoked as hoped for, etc. there are 2 httpd process, each of which has an instance of rotatelogs for error and one for access.
on one of the developer's Windows 7 laptop and our central development Windows 2008 R2 DataCenter server, however, the main httpd process kicks off 2 rotatelogs and the child httpd process kicks off only 1 (for error, if that is interesting).
unfortunately, the rotatelogs for error for the watchdog process is spiking the CPU -- the callstack reported from processexplorer is usually:
| Code: | ntoskrnl.exe!memset+0x82f
ntoskrnl.exe!IoFreeErrorLogEntry+0x3b3
ntoskrnl.exe!KeSynchronizeExecution+0x692
ntoskrnl.exe!KeStackAttachProcess+0x1ba6
ntoskrnl.exe!KeStackAttachProcess+0x1207
ntoskrnl.exe!PsReturnProcessNonPagedPoolQuota+0x84d
ntoskrnl.exe!ObCheckObjectAccess+0x971
ntoskrnl.exe!ObCheckObjectAccess+0xd7f
ntoskrnl.exe!KeSynchronizeExecution+0x3a23
ntdll.dll!NtUnmapViewOfSection+0xa
wow64.dll!Wow64EmulateAtlThunk+0x84cb
wow64.dll!Wow64SystemServiceEx+0xd7
wow64cpu.dll!TurboDispatchJumpAddressEnd+0x2d
wow64.dll!Wow64SystemServiceEx+0x1ce
wow64.dll!Wow64LdrpInitialize+0x42a
ntdll.dll!RtlUniform+0x6e6
ntdll.dll!EtwEventSetInformation+0x15158
ntdll.dll!LdrInitializeThunk+0xe
|
the contents of my batch file is fairly tame:
| Code: |
@echo off
set LOGFILE=%1
set THISDIR=%~dp0%
"%THISDIR%magic_console.exe" MaintainLogs.mas %LOGFILE%
|
which is just launching a program that does the maintenance. I inserted a call to EVENTCREATE just before the program call in order to log the commandline (in case there was a problem with my program call) but nothing logs, so I am pretty certain the batch file is not getting hit in the problematic instances. there are no entries logged to event viewer from rotatelogs and removing the -p switch makes everything hunky dory again.
the version of rotatelogs.exe shows 2.4.12.0, which I downloaded from here:
Apache, 2.4.12, win32:
sourced: https://www.apachelounge.com/download/ - 03/24/2015
does anyone have any guidance on what might be happening/where to go next? |
|
| Back to top |
|
rguilbault
Joined: 25 Jul 2015
Posts: 7
Location: USA
|
| Posted: Wed 12 Aug '15 22:10 Post subject: |
|
|
I was able to compile rotatelogs.exe with some trap code added, e.g.:
| Code: | int main (int argc, const char * const argv[])
{
char buf[BUFSIZE];
apr_size_t nRead, nWrite;
apr_file_t *f_stdin;
apr_file_t *f_stdout;
apr_getopt_t *opt;
apr_status_t rv;
char c;
const char *opt_arg;
const char *err = NULL;
#if APR_FILES_AS_SOCKETS
apr_pollfd_t pollfd = { 0 };
apr_status_t pollret = APR_SUCCESS;
int polltimeout;
#endif
FILE *f = fopen("C:\\Program Files (x86)\\Apache\\bin\\!stderr.log","w");
unsigned int pid = GetProcessId(GetCurrentProcess());
fprintf(f, "[%u] 0\n", pid);
fflush(f);
apr_app_initialize(&argc, &argv, NULL);
fprintf(f, "[%u] 1\n", pid);
fflush(f);
atexit(apr_terminate);
fprintf(f, "[%u] 2\n", pid);
fflush(f);
memset(&config, 0, sizeof config);
memset(&status, 0, sizeof status);
status.rotateReason = ROTATE_NONE;
apr_pool_create(&status.pool, NULL);
fprintf(f, "[%u] 3\n", pid);
fflush(f);
apr_getopt_init(&opt, status.pool, argc, argv);
fprintf(f, "[%u] 4\n", pid);
fflush(f);
|
I find that the rotatelogs.exe spawned from the child httpd process logs:
[9048] 0
[9048] 1
[9048] 2
[9048] 3
[9048] 4
[9048] 5: v - (null)
[9048] 5: p - maint/MaintainLogs.bat
[9048] prog: maint/MaintainLogs.bat
[9048] prog (after signal)
[9048] 5: l - (null)
[9048] 6
[9048] 7
[9048] 8
but the rotatelogs associated to the watchdog process are *not* putting anything to the log (in this test, it would be either pid 6768 or 5516).
as I begin logging before any function or loop is called, I'm thoroughly confused. and the references in the callstack all seem to point to https://msdn.microsoft.com/en-us/library/windows/desktop/hh447256%28v=vs.85%29.aspx or https://msdn.microsoft.com/en-us/library/windows/desktop/ms682489%28v=vs.85%29.aspx. |
|
| Back to top |
|
rguilbault
Joined: 25 Jul 2015
Posts: 7
Location: USA
|
| Posted: Wed 12 Aug '15 22:16 Post subject: |
|
|
lucky capture of a new/interesting callstack, perhaps:
ntoskrnl.exe!KeWaitForMultipleObjects+0xc0a
ntdll.dll!ZwMapViewOfSection+0xa
wow64.dll!Wow64EmulateAtlThunk+0x8325
wow64.dll!Wow64SystemServiceEx+0x1a8
wow64cpu.dll!TurboDispatchJumpAddressEnd+0x2d
wow64.dll!Wow64SystemServiceEx+0x1ce
wow64.dll!Wow64LdrpInitialize+0x42a
ntdll.dll!RtlUniform+0x6e6
ntdll.dll!RtlCreateTagHeap+0xa7
ntdll.dll!LdrInitializeThunk+0xe
ntdll.dll!ZwQuerySystemInformation+0x12
kernel32.dll!CreateToolhelp32Snapshot+0x5b
rotatelogs.exe!apr_proc_wait_all_procs+0xa5
rotatelogs.exe!post_rotate+0xc7
rotatelogs.exe!doRotate+0x211
rotatelogs.exe!main+0x483
rotatelogs.exe!__tmainCRTStartup+0x122
kernel32.dll!BaseThreadInitThunk+0x12
ntdll.dll!RtlInitializeExceptionChain+0x63
ntdll.dll!RtlInitializeExceptionChain+0x36 |
|
| Back to top |
|
rguilbault
Joined: 25 Jul 2015
Posts: 7
Location: USA
|
| Posted: Thu 13 Aug '15 0:31 Post subject: |
|
|
narrowing down futher, apr_proc_wait_all_procs returns APR_CHILD_DONE if there are no existing processes:
| Code: | if (nActive == 0) {
rv = APR_CHILD_DONE;
proc->pid = -1;
}
return rv;
} |
so the post-rotate logic gets caught up:
| Code: | while (apr_proc_wait_all_procs(&proc, NULL, NULL, APR_NOWAIT, pool) == APR_CHILD_DONE)
/* noop */; |
it almost feels like this should be != APR_CHILD_DONE (though it confuses me why I don't see the CPU spike on my laptop). |
|
| Back to top |
|
James Blond
Moderator
Joined: 19 Jan 2006
Posts: 7298
Location: Germany, Next to Hamburg
|
|
| Back to top |
|
rguilbault
Joined: 25 Jul 2015
Posts: 7
Location: USA
|
|
| Back to top |
|
|
|
|
|
|
