1
0
mirror of https://github.com/systemd/systemd.git synced 2024-11-14 15:21:37 +03:00
systemd/src/bootchart/store.c

529 lines
18 KiB
C
Raw Normal View History

/*-*- Mode: C; c-basic-offset: 8; indent-tabs-mode: nil -*-*/
/***
This file is part of systemd.
Copyright (C) 2009-2013 Intel Corporation
Authors:
Auke Kok <auke-jan.h.kok@intel.com>
systemd is free software; you can redistribute it and/or modify it
under the terms of the GNU Lesser General Public License as published by
the Free Software Foundation; either version 2.1 of the License, or
(at your option) any later version.
systemd is distributed in the hope that it will be useful, but
WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
Lesser General Public License for more details.
You should have received a copy of the GNU Lesser General Public License
along with systemd; If not, see <http://www.gnu.org/licenses/>.
***/
#include <unistd.h>
#include <stdlib.h>
#include <limits.h>
#include <stdio.h>
#include <string.h>
#include <dirent.h>
#include <fcntl.h>
#include <time.h>
#include "util.h"
2014-08-18 22:59:11 +04:00
#include "time-util.h"
#include "strxcpyx.h"
#include "store.h"
#include "bootchart.h"
2014-04-24 19:50:51 +04:00
#include "cgroup-util.h"
/*
* Alloc a static 4k buffer for stdio - primarily used to increase
* PSS buffering from the default 1k stdin buffer to reduce
* read() overhead.
*/
static char smaps_buf[4096];
static int skip = 0;
DIR *proc;
int procfd = -1;
double gettime_ns(void) {
struct timespec n;
clock_gettime(CLOCK_MONOTONIC, &n);
2014-08-18 22:59:11 +04:00
return (n.tv_sec + (n.tv_nsec / (double) NSEC_PER_SEC));
}
static double gettime_up(void) {
struct timespec n;
2013-01-10 01:38:03 +04:00
clock_gettime(CLOCK_BOOTTIME, &n);
2014-08-18 22:59:11 +04:00
return (n.tv_sec + (n.tv_nsec / (double) NSEC_PER_SEC));
}
2013-01-10 01:38:03 +04:00
void log_uptime(void) {
if (arg_relative)
graph_start = log_start = gettime_ns();
else {
double uptime = gettime_up();
log_start = gettime_ns();
2013-01-10 01:38:03 +04:00
graph_start = log_start - uptime;
}
}
static char *bufgetline(char *buf) {
2013-01-10 01:38:03 +04:00
char *c;
2013-01-10 01:38:03 +04:00
if (!buf)
return NULL;
2013-01-10 01:38:03 +04:00
c = strchr(buf, '\n');
if (c)
c++;
return c;
}
static int pid_cmdline_strscpy(char *buffer, size_t buf_len, int pid) {
char filename[PATH_MAX];
_cleanup_close_ int fd=-1;
ssize_t n;
sprintf(filename, "%d/cmdline", pid);
fd = openat(procfd, filename, O_RDONLY);
if (fd < 0)
return -errno;
n = read(fd, buffer, buf_len-1);
if (n > 0) {
int i;
for (i = 0; i < n; i++)
if (buffer[i] == '\0')
buffer[i] = ' ';
buffer[n] = '\0';
}
return 0;
}
int log_sample(int sample, struct list_sample_data **ptr) {
systemd-bootchart: Prevent closing random file descriptors If the kernel has no CONFIG_SCHED_DEBUG option set, systemd-bootchart produces empty .svg file. The reason for this is very fragile file descriptor logic in log_sample() and main() (/* do some cleanup, close fd's */ block). There are many places where file descriptors are closed on failure (missing SCHED_DEBUG provokes it), but there are several problems with it: - following iterations in the loop see that the descriptor is non zero and do not open the corresponding file again; - "some cleanup" code closes already closed files and the descriptors are reused already, in particular for resulting .svg file; - static "vmstat" and "schedstat" variables in log_sample() made the situation even worse. These are the strace fragments: [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) getdents64(4, /* 0 entries */, 32768) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 783843501}) = 0 nanosleep({0, 5221792}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 789726835}) = 0 lseek(4, 0, SEEK_SET) = 0 pread(5, "nr_free_pages 52309\nnr_alloc_bat"..., 4095, 0) = 685 pread(6, "version 15\ntimestamp 4294939775\n"..., 4095, 0) = 86 getdents64(4, /* 99 entries */, 32768) = 2680 pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(8, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(8) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(9, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(9) = -1 EBADF (Bad file descriptor) [...] where it obviously tries to close same and reused decriptors many times, also passing return code "-1" instead of descriptor... [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pipe2([7, 8], O_CLOEXEC) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb6fd0068) = 192 close(8) = 0 fcntl64(7, F_SETFD, 0) = 0 fstat64(7, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fd2000 read(7, "[ 0.074507] calling vfp_init"..., 4096) = 4096 [...] read(7, "s)\n[ 6.228910] UBIFS: reserve"..., 4096) = 4096 read(7, "trary Executable File Formats Fi"..., 4096) = 1616 read(7, "", 4096) = 0 close(7) = 0 wait4(192, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 192
2015-03-29 21:41:56 +03:00
static int vmstat = -1;
static int schedstat = -1;
char buf[4096];
2013-01-10 01:38:03 +04:00
char key[256];
char val[256];
char rt[256];
char wt[256];
char *m;
int c;
int p;
int mod;
static int e_fd = -1;
2013-01-10 01:38:03 +04:00
ssize_t s;
ssize_t n;
struct dirent *ent;
int fd;
struct list_sample_data *sampledata;
struct ps_sched_struct *ps_prev = NULL;
sampledata = *ptr;
/* all the per-process stuff goes here */
if (!proc) {
/* find all processes */
proc = opendir("/proc");
if (!proc)
return -errno;
procfd = dirfd(proc);
} else {
rewinddir(proc);
}
2013-01-10 01:38:03 +04:00
systemd-bootchart: Prevent closing random file descriptors If the kernel has no CONFIG_SCHED_DEBUG option set, systemd-bootchart produces empty .svg file. The reason for this is very fragile file descriptor logic in log_sample() and main() (/* do some cleanup, close fd's */ block). There are many places where file descriptors are closed on failure (missing SCHED_DEBUG provokes it), but there are several problems with it: - following iterations in the loop see that the descriptor is non zero and do not open the corresponding file again; - "some cleanup" code closes already closed files and the descriptors are reused already, in particular for resulting .svg file; - static "vmstat" and "schedstat" variables in log_sample() made the situation even worse. These are the strace fragments: [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) getdents64(4, /* 0 entries */, 32768) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 783843501}) = 0 nanosleep({0, 5221792}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 789726835}) = 0 lseek(4, 0, SEEK_SET) = 0 pread(5, "nr_free_pages 52309\nnr_alloc_bat"..., 4095, 0) = 685 pread(6, "version 15\ntimestamp 4294939775\n"..., 4095, 0) = 86 getdents64(4, /* 99 entries */, 32768) = 2680 pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(8, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(8) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(9, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(9) = -1 EBADF (Bad file descriptor) [...] where it obviously tries to close same and reused decriptors many times, also passing return code "-1" instead of descriptor... [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pipe2([7, 8], O_CLOEXEC) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb6fd0068) = 192 close(8) = 0 fcntl64(7, F_SETFD, 0) = 0 fstat64(7, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fd2000 read(7, "[ 0.074507] calling vfp_init"..., 4096) = 4096 [...] read(7, "s)\n[ 6.228910] UBIFS: reserve"..., 4096) = 4096 read(7, "trary Executable File Formats Fi"..., 4096) = 1616 read(7, "", 4096) = 0 close(7) = 0 wait4(192, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 192
2015-03-29 21:41:56 +03:00
if (vmstat < 0) {
2013-01-10 01:38:03 +04:00
/* block stuff */
vmstat = openat(procfd, "vmstat", O_RDONLY);
if (vmstat == -1)
return log_error_errno(errno, "Failed to open /proc/vmstat: %m");
2013-01-10 01:38:03 +04:00
}
n = pread(vmstat, buf, sizeof(buf) - 1, 0);
if (n <= 0) {
vmstat = safe_close(vmstat);
if (n < 0)
return -errno;
return -ENODATA;
2013-01-10 01:38:03 +04:00
}
buf[n] = '\0';
m = buf;
while (m) {
if (sscanf(m, "%s %s", key, val) < 2)
goto vmstat_next;
if (streq(key, "pgpgin"))
sampledata->blockstat.bi = atoi(val);
if (streq(key, "pgpgout")) {
sampledata->blockstat.bo = atoi(val);
2013-01-10 01:38:03 +04:00
break;
}
vmstat_next:
2013-01-10 01:38:03 +04:00
m = bufgetline(m);
if (!m)
break;
}
systemd-bootchart: Prevent closing random file descriptors If the kernel has no CONFIG_SCHED_DEBUG option set, systemd-bootchart produces empty .svg file. The reason for this is very fragile file descriptor logic in log_sample() and main() (/* do some cleanup, close fd's */ block). There are many places where file descriptors are closed on failure (missing SCHED_DEBUG provokes it), but there are several problems with it: - following iterations in the loop see that the descriptor is non zero and do not open the corresponding file again; - "some cleanup" code closes already closed files and the descriptors are reused already, in particular for resulting .svg file; - static "vmstat" and "schedstat" variables in log_sample() made the situation even worse. These are the strace fragments: [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) getdents64(4, /* 0 entries */, 32768) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 783843501}) = 0 nanosleep({0, 5221792}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 789726835}) = 0 lseek(4, 0, SEEK_SET) = 0 pread(5, "nr_free_pages 52309\nnr_alloc_bat"..., 4095, 0) = 685 pread(6, "version 15\ntimestamp 4294939775\n"..., 4095, 0) = 86 getdents64(4, /* 99 entries */, 32768) = 2680 pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(8, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(8) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(9, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(9) = -1 EBADF (Bad file descriptor) [...] where it obviously tries to close same and reused decriptors many times, also passing return code "-1" instead of descriptor... [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pipe2([7, 8], O_CLOEXEC) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb6fd0068) = 192 close(8) = 0 fcntl64(7, F_SETFD, 0) = 0 fstat64(7, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fd2000 read(7, "[ 0.074507] calling vfp_init"..., 4096) = 4096 [...] read(7, "s)\n[ 6.228910] UBIFS: reserve"..., 4096) = 4096 read(7, "trary Executable File Formats Fi"..., 4096) = 1616 read(7, "", 4096) = 0 close(7) = 0 wait4(192, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 192
2015-03-29 21:41:56 +03:00
if (schedstat < 0) {
2013-01-10 01:38:03 +04:00
/* overall CPU utilization */
schedstat = openat(procfd, "schedstat", O_RDONLY);
if (schedstat == -1)
return log_error_errno(errno, "Failed to open /proc/schedstat (requires CONFIG_SCHEDSTATS=y in kernel config): %m");
2013-01-10 01:38:03 +04:00
}
n = pread(schedstat, buf, sizeof(buf) - 1, 0);
if (n <= 0) {
schedstat = safe_close(schedstat);
if (n < 0)
return -errno;
return -ENODATA;
2013-01-10 01:38:03 +04:00
}
buf[n] = '\0';
m = buf;
while (m) {
int r;
2013-01-10 01:38:03 +04:00
if (sscanf(m, "%s %*s %*s %*s %*s %*s %*s %s %s", key, rt, wt) < 3)
goto schedstat_next;
if (strstr(key, "cpu")) {
r = safe_atoi((const char*)(key+3), &c);
if (r < 0 || c > MAXCPUS -1)
2013-01-10 01:38:03 +04:00
/* Oops, we only have room for MAXCPUS data */
break;
sampledata->runtime[c] = atoll(rt);
sampledata->waittime[c] = atoll(wt);
2013-01-10 01:38:03 +04:00
if (c == cpus)
cpus = c + 1;
}
schedstat_next:
2013-01-10 01:38:03 +04:00
m = bufgetline(m);
if (!m)
break;
}
if (arg_entropy) {
if (e_fd < 0) {
e_fd = openat(procfd, "sys/kernel/random/entropy_avail", O_RDONLY);
if (e_fd == -1)
return log_error_errno(errno, "Failed to open /proc/sys/kernel/random/entropy_avail: %m");
2013-01-10 01:38:03 +04:00
}
n = pread(e_fd, buf, sizeof(buf) - 1, 0);
if (n <= 0) {
close(e_fd);
e_fd = -1;
} else {
buf[n] = '\0';
sampledata->entropy_avail = atoi(buf);
2013-01-10 01:38:03 +04:00
}
}
while ((ent = readdir(proc)) != NULL) {
char filename[PATH_MAX];
int pid;
struct ps_struct *ps;
if ((ent->d_name[0] < '0') || (ent->d_name[0] > '9'))
continue;
pid = atoi(ent->d_name);
if (pid >= MAXPIDS)
continue;
ps = ps_first;
while (ps->next_ps) {
ps = ps->next_ps;
if (ps->pid == pid)
break;
}
/* end of our LL? then append a new record */
if (ps->pid != pid) {
_cleanup_fclose_ FILE *st = NULL;
2013-01-10 01:38:03 +04:00
char t[32];
struct ps_struct *parent;
int r;
2013-01-10 01:38:03 +04:00
ps->next_ps = new0(struct ps_struct, 1);
if (!ps->next_ps)
return log_oom();
2013-01-10 01:38:03 +04:00
ps = ps->next_ps;
ps->pid = pid;
systemd-bootchart: Prevent closing random file descriptors If the kernel has no CONFIG_SCHED_DEBUG option set, systemd-bootchart produces empty .svg file. The reason for this is very fragile file descriptor logic in log_sample() and main() (/* do some cleanup, close fd's */ block). There are many places where file descriptors are closed on failure (missing SCHED_DEBUG provokes it), but there are several problems with it: - following iterations in the loop see that the descriptor is non zero and do not open the corresponding file again; - "some cleanup" code closes already closed files and the descriptors are reused already, in particular for resulting .svg file; - static "vmstat" and "schedstat" variables in log_sample() made the situation even worse. These are the strace fragments: [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) getdents64(4, /* 0 entries */, 32768) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 783843501}) = 0 nanosleep({0, 5221792}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 789726835}) = 0 lseek(4, 0, SEEK_SET) = 0 pread(5, "nr_free_pages 52309\nnr_alloc_bat"..., 4095, 0) = 685 pread(6, "version 15\ntimestamp 4294939775\n"..., 4095, 0) = 86 getdents64(4, /* 99 entries */, 32768) = 2680 pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(8, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(8) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(9, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(9) = -1 EBADF (Bad file descriptor) [...] where it obviously tries to close same and reused decriptors many times, also passing return code "-1" instead of descriptor... [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pipe2([7, 8], O_CLOEXEC) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb6fd0068) = 192 close(8) = 0 fcntl64(7, F_SETFD, 0) = 0 fstat64(7, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fd2000 read(7, "[ 0.074507] calling vfp_init"..., 4096) = 4096 [...] read(7, "s)\n[ 6.228910] UBIFS: reserve"..., 4096) = 4096 read(7, "trary Executable File Formats Fi"..., 4096) = 1616 read(7, "", 4096) = 0 close(7) = 0 wait4(192, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 192
2015-03-29 21:41:56 +03:00
ps->sched = -1;
ps->schedstat = -1;
2013-01-10 01:38:03 +04:00
ps->sample = new0(struct ps_sched_struct, 1);
if (!ps->sample)
return log_oom();
ps->sample->sampledata = sampledata;
2013-01-10 01:38:03 +04:00
pscount++;
/* mark our first sample */
ps->first = ps->last = ps->sample;
ps->sample->runtime = atoll(rt);
ps->sample->waittime = atoll(wt);
2013-01-10 01:38:03 +04:00
/* get name, start time */
systemd-bootchart: Prevent closing random file descriptors If the kernel has no CONFIG_SCHED_DEBUG option set, systemd-bootchart produces empty .svg file. The reason for this is very fragile file descriptor logic in log_sample() and main() (/* do some cleanup, close fd's */ block). There are many places where file descriptors are closed on failure (missing SCHED_DEBUG provokes it), but there are several problems with it: - following iterations in the loop see that the descriptor is non zero and do not open the corresponding file again; - "some cleanup" code closes already closed files and the descriptors are reused already, in particular for resulting .svg file; - static "vmstat" and "schedstat" variables in log_sample() made the situation even worse. These are the strace fragments: [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) getdents64(4, /* 0 entries */, 32768) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 783843501}) = 0 nanosleep({0, 5221792}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 789726835}) = 0 lseek(4, 0, SEEK_SET) = 0 pread(5, "nr_free_pages 52309\nnr_alloc_bat"..., 4095, 0) = 685 pread(6, "version 15\ntimestamp 4294939775\n"..., 4095, 0) = 86 getdents64(4, /* 99 entries */, 32768) = 2680 pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(8, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(8) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(9, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(9) = -1 EBADF (Bad file descriptor) [...] where it obviously tries to close same and reused decriptors many times, also passing return code "-1" instead of descriptor... [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pipe2([7, 8], O_CLOEXEC) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb6fd0068) = 192 close(8) = 0 fcntl64(7, F_SETFD, 0) = 0 fstat64(7, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fd2000 read(7, "[ 0.074507] calling vfp_init"..., 4096) = 4096 [...] read(7, "s)\n[ 6.228910] UBIFS: reserve"..., 4096) = 4096 read(7, "trary Executable File Formats Fi"..., 4096) = 1616 read(7, "", 4096) = 0 close(7) = 0 wait4(192, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 192
2015-03-29 21:41:56 +03:00
if (ps->sched < 0) {
sprintf(filename, "%d/sched", pid);
ps->sched = openat(procfd, filename, O_RDONLY);
2013-01-10 01:38:03 +04:00
if (ps->sched == -1)
continue;
}
s = pread(ps->sched, buf, sizeof(buf) - 1, 0);
if (s <= 0) {
close(ps->sched);
systemd-bootchart: Prevent closing random file descriptors If the kernel has no CONFIG_SCHED_DEBUG option set, systemd-bootchart produces empty .svg file. The reason for this is very fragile file descriptor logic in log_sample() and main() (/* do some cleanup, close fd's */ block). There are many places where file descriptors are closed on failure (missing SCHED_DEBUG provokes it), but there are several problems with it: - following iterations in the loop see that the descriptor is non zero and do not open the corresponding file again; - "some cleanup" code closes already closed files and the descriptors are reused already, in particular for resulting .svg file; - static "vmstat" and "schedstat" variables in log_sample() made the situation even worse. These are the strace fragments: [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) getdents64(4, /* 0 entries */, 32768) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 783843501}) = 0 nanosleep({0, 5221792}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 789726835}) = 0 lseek(4, 0, SEEK_SET) = 0 pread(5, "nr_free_pages 52309\nnr_alloc_bat"..., 4095, 0) = 685 pread(6, "version 15\ntimestamp 4294939775\n"..., 4095, 0) = 86 getdents64(4, /* 99 entries */, 32768) = 2680 pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(8, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(8) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(9, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(9) = -1 EBADF (Bad file descriptor) [...] where it obviously tries to close same and reused decriptors many times, also passing return code "-1" instead of descriptor... [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pipe2([7, 8], O_CLOEXEC) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb6fd0068) = 192 close(8) = 0 fcntl64(7, F_SETFD, 0) = 0 fstat64(7, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fd2000 read(7, "[ 0.074507] calling vfp_init"..., 4096) = 4096 [...] read(7, "s)\n[ 6.228910] UBIFS: reserve"..., 4096) = 4096 read(7, "trary Executable File Formats Fi"..., 4096) = 1616 read(7, "", 4096) = 0 close(7) = 0 wait4(192, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 192
2015-03-29 21:41:56 +03:00
ps->sched = -1;
2013-01-10 01:38:03 +04:00
continue;
}
buf[s] = '\0';
2013-01-10 01:38:03 +04:00
if (!sscanf(buf, "%s %*s %*s", key))
continue;
strscpy(ps->name, sizeof(ps->name), key);
/* cmdline */
if (arg_show_cmdline)
pid_cmdline_strscpy(ps->name, sizeof(ps->name), pid);
2013-01-10 01:38:03 +04:00
/* discard line 2 */
m = bufgetline(buf);
if (!m)
continue;
m = bufgetline(m);
if (!m)
continue;
if (!sscanf(m, "%*s %*s %s", t))
continue;
r = safe_atod(t, &ps->starttime);
if (r < 0)
continue;
ps->starttime /= 1000.0;
2013-01-10 01:38:03 +04:00
2014-04-24 19:50:51 +04:00
if (arg_show_cgroup)
/* if this fails, that's OK */
cg_pid_get_path(SYSTEMD_CGROUP_CONTROLLER,
ps->pid, &ps->cgroup);
2013-01-10 01:38:03 +04:00
/* ppid */
sprintf(filename, "%d/stat", pid);
fd = openat(procfd, filename, O_RDONLY);
if (fd == -1)
continue;
st = fdopen(fd, "r");
if (!st) {
close(fd);
2013-01-10 01:38:03 +04:00
continue;
}
2013-01-10 01:38:03 +04:00
if (!fscanf(st, "%*s %*s %*s %i", &p)) {
continue;
}
ps->ppid = p;
/*
* setup child pointers
*
* these are used to paint the tree coherently later
* each parent has a LL of children, and a LL of siblings
*/
if (pid == 1)
continue; /* nothing to do for init atm */
/* kthreadd has ppid=0, which breaks our tree ordering */
if (ps->ppid == 0)
ps->ppid = 1;
parent = ps_first;
while ((parent->next_ps && parent->pid != ps->ppid))
parent = parent->next_ps;
if (parent->pid != ps->ppid) {
2013-01-10 01:38:03 +04:00
/* orphan */
ps->ppid = 1;
parent = ps_first->next_ps;
}
ps->parent = parent;
if (!parent->children) {
/* it's the first child */
parent->children = ps;
} else {
/* walk all children and append */
struct ps_struct *children;
children = parent->children;
while (children->next)
children = children->next;
children->next = ps;
}
}
/* else -> found pid, append data in ps */
/* below here is all continuous logging parts - we get here on every
* iteration */
/* rt, wt */
systemd-bootchart: Prevent closing random file descriptors If the kernel has no CONFIG_SCHED_DEBUG option set, systemd-bootchart produces empty .svg file. The reason for this is very fragile file descriptor logic in log_sample() and main() (/* do some cleanup, close fd's */ block). There are many places where file descriptors are closed on failure (missing SCHED_DEBUG provokes it), but there are several problems with it: - following iterations in the loop see that the descriptor is non zero and do not open the corresponding file again; - "some cleanup" code closes already closed files and the descriptors are reused already, in particular for resulting .svg file; - static "vmstat" and "schedstat" variables in log_sample() made the situation even worse. These are the strace fragments: [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) getdents64(4, /* 0 entries */, 32768) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 783843501}) = 0 nanosleep({0, 5221792}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 789726835}) = 0 lseek(4, 0, SEEK_SET) = 0 pread(5, "nr_free_pages 52309\nnr_alloc_bat"..., 4095, 0) = 685 pread(6, "version 15\ntimestamp 4294939775\n"..., 4095, 0) = 86 getdents64(4, /* 99 entries */, 32768) = 2680 pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(8, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(8) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(9, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(9) = -1 EBADF (Bad file descriptor) [...] where it obviously tries to close same and reused decriptors many times, also passing return code "-1" instead of descriptor... [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pipe2([7, 8], O_CLOEXEC) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb6fd0068) = 192 close(8) = 0 fcntl64(7, F_SETFD, 0) = 0 fstat64(7, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fd2000 read(7, "[ 0.074507] calling vfp_init"..., 4096) = 4096 [...] read(7, "s)\n[ 6.228910] UBIFS: reserve"..., 4096) = 4096 read(7, "trary Executable File Formats Fi"..., 4096) = 1616 read(7, "", 4096) = 0 close(7) = 0 wait4(192, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 192
2015-03-29 21:41:56 +03:00
if (ps->schedstat < 0) {
sprintf(filename, "%d/schedstat", pid);
ps->schedstat = openat(procfd, filename, O_RDONLY);
2013-01-10 01:38:03 +04:00
if (ps->schedstat == -1)
continue;
}
s = pread(ps->schedstat, buf, sizeof(buf) - 1, 0);
if (s <= 0) {
2013-01-10 01:38:03 +04:00
/* clean up our file descriptors - assume that the process exited */
close(ps->schedstat);
systemd-bootchart: Prevent closing random file descriptors If the kernel has no CONFIG_SCHED_DEBUG option set, systemd-bootchart produces empty .svg file. The reason for this is very fragile file descriptor logic in log_sample() and main() (/* do some cleanup, close fd's */ block). There are many places where file descriptors are closed on failure (missing SCHED_DEBUG provokes it), but there are several problems with it: - following iterations in the loop see that the descriptor is non zero and do not open the corresponding file again; - "some cleanup" code closes already closed files and the descriptors are reused already, in particular for resulting .svg file; - static "vmstat" and "schedstat" variables in log_sample() made the situation even worse. These are the strace fragments: [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) getdents64(4, /* 0 entries */, 32768) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 783843501}) = 0 nanosleep({0, 5221792}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 789726835}) = 0 lseek(4, 0, SEEK_SET) = 0 pread(5, "nr_free_pages 52309\nnr_alloc_bat"..., 4095, 0) = 685 pread(6, "version 15\ntimestamp 4294939775\n"..., 4095, 0) = 86 getdents64(4, /* 99 entries */, 32768) = 2680 pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(8, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(8) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(9, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(9) = -1 EBADF (Bad file descriptor) [...] where it obviously tries to close same and reused decriptors many times, also passing return code "-1" instead of descriptor... [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pipe2([7, 8], O_CLOEXEC) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb6fd0068) = 192 close(8) = 0 fcntl64(7, F_SETFD, 0) = 0 fstat64(7, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fd2000 read(7, "[ 0.074507] calling vfp_init"..., 4096) = 4096 [...] read(7, "s)\n[ 6.228910] UBIFS: reserve"..., 4096) = 4096 read(7, "trary Executable File Formats Fi"..., 4096) = 1616 read(7, "", 4096) = 0 close(7) = 0 wait4(192, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 192
2015-03-29 21:41:56 +03:00
ps->schedstat = -1;
if (ps->sched) {
2013-01-10 01:38:03 +04:00
close(ps->sched);
systemd-bootchart: Prevent closing random file descriptors If the kernel has no CONFIG_SCHED_DEBUG option set, systemd-bootchart produces empty .svg file. The reason for this is very fragile file descriptor logic in log_sample() and main() (/* do some cleanup, close fd's */ block). There are many places where file descriptors are closed on failure (missing SCHED_DEBUG provokes it), but there are several problems with it: - following iterations in the loop see that the descriptor is non zero and do not open the corresponding file again; - "some cleanup" code closes already closed files and the descriptors are reused already, in particular for resulting .svg file; - static "vmstat" and "schedstat" variables in log_sample() made the situation even worse. These are the strace fragments: [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) getdents64(4, /* 0 entries */, 32768) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 783843501}) = 0 nanosleep({0, 5221792}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 789726835}) = 0 lseek(4, 0, SEEK_SET) = 0 pread(5, "nr_free_pages 52309\nnr_alloc_bat"..., 4095, 0) = 685 pread(6, "version 15\ntimestamp 4294939775\n"..., 4095, 0) = 86 getdents64(4, /* 99 entries */, 32768) = 2680 pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(8, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(8) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(9, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(9) = -1 EBADF (Bad file descriptor) [...] where it obviously tries to close same and reused decriptors many times, also passing return code "-1" instead of descriptor... [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pipe2([7, 8], O_CLOEXEC) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb6fd0068) = 192 close(8) = 0 fcntl64(7, F_SETFD, 0) = 0 fstat64(7, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fd2000 read(7, "[ 0.074507] calling vfp_init"..., 4096) = 4096 [...] read(7, "s)\n[ 6.228910] UBIFS: reserve"..., 4096) = 4096 read(7, "trary Executable File Formats Fi"..., 4096) = 1616 read(7, "", 4096) = 0 close(7) = 0 wait4(192, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 192
2015-03-29 21:41:56 +03:00
ps->sched = -1;
}
2013-01-10 01:38:03 +04:00
//if (ps->smaps)
// fclose(ps->smaps);
continue;
}
buf[s] = '\0';
2013-01-10 01:38:03 +04:00
if (!sscanf(buf, "%s %s %*s", rt, wt))
continue;
ps->sample->next = new0(struct ps_sched_struct, 1);
if (!ps->sample->next)
return log_oom();
ps->sample->next->prev = ps->sample;
ps->sample = ps->sample->next;
ps->last = ps->sample;
ps->sample->runtime = atoll(rt);
ps->sample->waittime = atoll(wt);
ps->sample->sampledata = sampledata;
ps->sample->ps_new = ps;
if (ps_prev) {
ps_prev->cross = ps->sample;
}
ps_prev = ps->sample;
ps->total = (ps->last->runtime - ps->first->runtime)
/ 1000000000.0;
2013-01-10 01:38:03 +04:00
if (!arg_pss)
2013-01-10 01:38:03 +04:00
goto catch_rename;
2013-01-10 01:38:03 +04:00
/* Pss */
if (!ps->smaps) {
sprintf(filename, "%d/smaps", pid);
fd = openat(procfd, filename, O_RDONLY);
if (fd == -1)
continue;
ps->smaps = fdopen(fd, "r");
if (!ps->smaps) {
close(fd);
2013-01-10 01:38:03 +04:00
continue;
}
2013-01-10 01:38:03 +04:00
setvbuf(ps->smaps, smaps_buf, _IOFBF, sizeof(smaps_buf));
}
else {
rewind(ps->smaps);
}
/* test to see if we need to skip another field */
if (skip == 0) {
if (fgets(buf, sizeof(buf), ps->smaps) == NULL) {
continue;
}
if (fread(buf, 1, 28 * 15, ps->smaps) != (28 * 15)) {
continue;
}
if (buf[392] == 'V') {
skip = 2;
}
else {
skip = 1;
}
2013-01-10 01:38:03 +04:00
rewind(ps->smaps);
}
while (1) {
int pss_kb;
/* skip one line, this contains the object mapped. */
if (fgets(buf, sizeof(buf), ps->smaps) == NULL) {
2013-01-10 01:38:03 +04:00
break;
}
2013-01-10 01:38:03 +04:00
/* then there's a 28 char 14 line block */
if (fread(buf, 1, 28 * 14, ps->smaps) != 28 * 14) {
2013-01-10 01:38:03 +04:00
break;
}
2013-01-10 01:38:03 +04:00
pss_kb = atoi(&buf[61]);
ps->sample->pss += pss_kb;
2013-01-10 01:38:03 +04:00
/* skip one more line if this is a newer kernel */
if (skip == 2) {
if (fgets(buf, sizeof(buf), ps->smaps) == NULL)
break;
}
}
if (ps->sample->pss > ps->pss_max)
ps->pss_max = ps->sample->pss;
catch_rename:
2013-01-10 01:38:03 +04:00
/* catch process rename, try to randomize time */
mod = (arg_hz < 4.0) ? 4.0 : (arg_hz / 4.0);
if (((samples - ps->pid) + pid) % (int)(mod) == 0) {
2013-01-10 01:38:03 +04:00
/* re-fetch name */
/* get name, start time */
if (!ps->sched) {
sprintf(filename, "%d/sched", pid);
ps->sched = openat(procfd, filename, O_RDONLY);
2013-01-10 01:38:03 +04:00
if (ps->sched == -1)
continue;
}
s = pread(ps->sched, buf, sizeof(buf) - 1, 0);
if (s <= 0) {
2013-01-10 01:38:03 +04:00
/* clean up file descriptors */
close(ps->sched);
systemd-bootchart: Prevent closing random file descriptors If the kernel has no CONFIG_SCHED_DEBUG option set, systemd-bootchart produces empty .svg file. The reason for this is very fragile file descriptor logic in log_sample() and main() (/* do some cleanup, close fd's */ block). There are many places where file descriptors are closed on failure (missing SCHED_DEBUG provokes it), but there are several problems with it: - following iterations in the loop see that the descriptor is non zero and do not open the corresponding file again; - "some cleanup" code closes already closed files and the descriptors are reused already, in particular for resulting .svg file; - static "vmstat" and "schedstat" variables in log_sample() made the situation even worse. These are the strace fragments: [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) getdents64(4, /* 0 entries */, 32768) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 783843501}) = 0 nanosleep({0, 5221792}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 789726835}) = 0 lseek(4, 0, SEEK_SET) = 0 pread(5, "nr_free_pages 52309\nnr_alloc_bat"..., 4095, 0) = 685 pread(6, "version 15\ntimestamp 4294939775\n"..., 4095, 0) = 86 getdents64(4, /* 99 entries */, 32768) = 2680 pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(8, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(8) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(9, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(9) = -1 EBADF (Bad file descriptor) [...] where it obviously tries to close same and reused decriptors many times, also passing return code "-1" instead of descriptor... [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pipe2([7, 8], O_CLOEXEC) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb6fd0068) = 192 close(8) = 0 fcntl64(7, F_SETFD, 0) = 0 fstat64(7, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fd2000 read(7, "[ 0.074507] calling vfp_init"..., 4096) = 4096 [...] read(7, "s)\n[ 6.228910] UBIFS: reserve"..., 4096) = 4096 read(7, "trary Executable File Formats Fi"..., 4096) = 1616 read(7, "", 4096) = 0 close(7) = 0 wait4(192, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 192
2015-03-29 21:41:56 +03:00
ps->sched = -1;
if (ps->schedstat) {
2013-01-10 01:38:03 +04:00
close(ps->schedstat);
systemd-bootchart: Prevent closing random file descriptors If the kernel has no CONFIG_SCHED_DEBUG option set, systemd-bootchart produces empty .svg file. The reason for this is very fragile file descriptor logic in log_sample() and main() (/* do some cleanup, close fd's */ block). There are many places where file descriptors are closed on failure (missing SCHED_DEBUG provokes it), but there are several problems with it: - following iterations in the loop see that the descriptor is non zero and do not open the corresponding file again; - "some cleanup" code closes already closed files and the descriptors are reused already, in particular for resulting .svg file; - static "vmstat" and "schedstat" variables in log_sample() made the situation even worse. These are the strace fragments: [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) getdents64(4, /* 0 entries */, 32768) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 783843501}) = 0 nanosleep({0, 5221792}, NULL) = 0 clock_gettime(CLOCK_MONOTONIC, {24, 789726835}) = 0 lseek(4, 0, SEEK_SET) = 0 pread(5, "nr_free_pages 52309\nnr_alloc_bat"..., 4095, 0) = 685 pread(6, "version 15\ntimestamp 4294939775\n"..., 4095, 0) = 86 getdents64(4, /* 99 entries */, 32768) = 2680 pread(7, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(8, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(8) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pread(9, 0xbea60a2c, 4095, 0) = -1 EBADF (Bad file descriptor) close(9) = -1 EBADF (Bad file descriptor) [...] where it obviously tries to close same and reused decriptors many times, also passing return code "-1" instead of descriptor... [...] close(7) = -1 EBADF (Bad file descriptor) close(-1) = -1 EBADF (Bad file descriptor) pipe2([7, 8], O_CLOEXEC) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb6fd0068) = 192 close(8) = 0 fcntl64(7, F_SETFD, 0) = 0 fstat64(7, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6fd2000 read(7, "[ 0.074507] calling vfp_init"..., 4096) = 4096 [...] read(7, "s)\n[ 6.228910] UBIFS: reserve"..., 4096) = 4096 read(7, "trary Executable File Formats Fi"..., 4096) = 1616 read(7, "", 4096) = 0 close(7) = 0 wait4(192, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 192
2015-03-29 21:41:56 +03:00
ps->schedstat = -1;
}
2013-01-10 01:38:03 +04:00
//if (ps->smaps)
// fclose(ps->smaps);
continue;
}
buf[s] = '\0';
2013-01-10 01:38:03 +04:00
if (!sscanf(buf, "%s %*s %*s", key))
continue;
strscpy(ps->name, sizeof(ps->name), key);
/* cmdline */
if (arg_show_cmdline)
pid_cmdline_strscpy(ps->name, sizeof(ps->name), pid);
2013-01-10 01:38:03 +04:00
}
}
return 0;
}