fork() 50 times slower on some Linux kernels?

[Elmar]

Dear all,

a previous discussion in this group mentioned the problem that fork()
is a resource bottleneck because it needs to (virtually) duplicate a
process' memory space:

http://groups.google.com/group/comp.lang.c/browse_thread/thread/911978685974e041/bdd37113d7b43e0c

Here comes a surprising example:

The program below first allocates 500 MB, and then calls the function
system("ls Hello"), which just uses the shell 'ls' command to list a
file named 'Hello', and finally prints the time required:

#include <sys/time.h>
#include <stdio.h>
#include <malloc.h>
#include <string.h>

#define ALLOCSIZE (500*1024*1024)

int main(int argc,char **argv)
{ void *mem;
struct timeval before,after;

mem=malloc(ALLOCSIZE);
/* IF THE memset IS COMMENTED OUT, THE system CALL IS FAST */
memset(mem,0,ALLOCSIZE);
gettimeofday(&before,NULL);
system("ls Hello");
gettimeofday(&after,NULL);
printf("Time before: %d.%06d\n",before.tv_sec,before.tv_usec);
printf("Time after: %d.%06d\n",after.tv_sec,after.tv_usec); }


On my Intel Core i7 with 8GB RAM/20 GB swap (64bit, CentOS uname
2.6.18-238.5.1.el5 #1 SMP Fri Apr 1 18:41:58 EDT 2011 x86_64), the
output is as follows:

ls: Hello: No such file or directory
Time before: 1326139795.216646
Time after: 1326139796.137364

So it takes almost *one second* to execute the shell command. If the
'memset' is commented out, so that the allocated memory is not
touched, the system call completes instantly:

ls: Hello: No such file or directory
Time before: 1326139934.344964
Time after: 1326139934.359046

Interestingly, the slowness seems to be kernel dependent. On my other
old, slow computer, a Core2Duo with 1GB RAM/2 GB swap (32bit, Fedora
Core uname 2.6.19-1.2895.fc6 #1 SMP Wed Jan 10 19:28:18 EST 2007 i686
i686 i386 GNU/Linux), it completes instantly, also with memset
present:

ls: Hello: No such file or directory
Time before: 1326140333.832788
Time after: 1326140333.853900

The enormous slowness on kernel 2.6.18-238.5.1 kills me, because my
application needs to make about ~20 system calls during startup and
thus needs 20 seconds to start!

Google didn't help much, so my hope was that one of you has heard of/
encountered this problem, knows which kernels are affected, and when/
how it was solved, maybe there is a configuration trick etc.?

Many thanks for your help,
Elmar

P.S.: It seems that also others are affected:
http://stackoverflow.com/questions/5399030/clone-fork-process-creation-is-slow-on-some-machines

 

[Ian Collins]

Dear all,

a previous discussion in this group mentioned the problem that fork()
is a resource bottleneck because it needs to (virtually) duplicate a
process' memory space:

This post belongs on a Linux development group, not here.

 

[Kaz Kylheku]

Interestingly, the slowness seems to be kernel dependent.

How can you conclude that, when at the same time you are changing
these variables:

- architecture (x86_64 vs ia32)
- hardware (different box)
- different distro (CentOS vs Fedora)

 

[Stephen Sprunk]

a previous discussion in this group mentioned the problem that fork()
is a resource bottleneck because it needs to (virtually) duplicate a
process' memory space:

http://groups.google.com/group/comp.lang.c/browse_thread/thread/911978685974e041/bdd37113d7b43e0c
...
Google didn't help much, so my hope was that one of you has heard of/
encountered this problem, knows which kernels are affected, and when/
how it was solved, maybe there is a configuration trick etc.?

Did you read that thread? The answer is in there, and it has nothing to
do with the kernel versions; it's about whether vm overcommitment is
enabled (fast but unsafe) or disabled (safe but unfast).

S

 

[Jens Thoms Toerring]

Sorry, would have redirected this to a Linux or Unix group
but too much of the original information has been snipped
to be of any use over there, thus only the [OT] markers...

To the OP: please repost on comp.os.linux.development.apps
or comp.unix.programmer or similar where it would be on-
topic.

How can you conclude that, when at the same time you are changing
these variables:

- architecture (x86_64 vs ia32)
- hardware (different box)
- different distro (CentOS vs Fedora)

I guess the worrying thing is the difference it seems make
if the memory is set or not. On my system (but with a 3.0
kernel) I also see a difference, but at a much smaller scale
- when the 500MB are set to 0 the system() call takes about
15 ms (what the OP called "instantly";-) while without it's
only 2.5 ms (both rather consistently). Not easily explained
when assuming a simple COW-behaviour on fork. If this would
be a Linux group I might even be tempted into booting an ol-
der kernel to see what a difference that makes on the exact
same hardware;-)
Regards, Jens

 

[Kaz Kylheku]

Did you read that thread? The answer is in there, and it has nothing to
do with the kernel versions; it's about whether vm overcommitment is
enabled (fast but unsafe) or disabled (safe but unfast).

That's going to be moot in this issue that he's having. Strict overcommit
accounting only makes a difference to whether a call to mmap succeeds or
fails. Allocation of the mmaps is still lazy. The OS merely ensures (sort of)
that it has the "cash" to back the "check" it has written (i.e. that's exactly
why this is called accounting!) ``If we hand out this virtual space, will there
later be enough pages available to populate it?'' If the answer is no, then the
mmap is denied (ENOMEM).

(This accounting method isn't accurate, because the kernel OS can allocate pages
for itself which are not accounted. That's why there is the percentage fudge
factor ``make the total virtual memory outlay no more than XXX% relative
to total core and swap''. If you make this 100, it is not strict enough because
it allows as much total virtual memory as there is physical storage, with no
space for kernel pages. But there is no guarantee that, say, 80% is enough,
either, in every conceivable situation. Why not just add the kernel pages
to the accounting? Then VM will be counted twice, because mmap regions are
populated by the same kernel allocations! You would have to categorize kernel
get_free_page calls into those which go into populating anonymous mmaps, and
those which go elsewhere.)

Overcommit accounting is also moot if you memset the memory, because then
you're committing it immediately (taking the check written by mmap straight to
the bank to get it in cash).

In any case, did you notice in the original posting that this 1 second
pause occurs on a system with 8GB of RAM?

 

[Kaz Kylheku]

Sorry, would have redirected this to a Linux or Unix group
but too much of the original information has been snipped
to be of any use over there, thus only the [OT] markers...

Sure, because Usenet discussion traffic has grown to such staggering volumes,
that we can't possibly deal with any off-topic drift.

 

[Ian Collins]

Sorry, would have redirected this to a Linux or Unix group
but too much of the original information has been snipped
to be of any use over there, thus only the [OT] markers...

Sure, because Usenet discussion traffic has grown to such staggering volumes,
that we can't possibly deal with any off-topic drift.

That's not really the point, is it? If someone wants to start a
discussion on topic X, a group dedicated to topic X is the place to ask.
Sending them there is the best response elsewhere.

 

[Stephen Sprunk]

That's going to be moot in this issue that he's having. Strict overcommit
accounting only makes a difference to whether a call to mmap succeeds or
fails. Allocation of the mmaps is still lazy. The OS merely ensures (sort of)
that it has the "cash" to back the "check" it has written (i.e. that's exactly
why this is called accounting!) ``If we hand out this virtual space, will there
later be enough pages available to populate it?'' If the answer is no, then the
mmap is denied (ENOMEM).

We're not talking about mmap() here; we're talking about fork().

When you fork(), all the pages in the parent process are shared with the
child, with copy-on-write behavior. When overcommitment is enabled,
there is no backing guaranteed for those potential future copies, and
modifying them (in either process) forces the kernel to find backing at
some unspecified point in the future--which may fail. Disabling
overcommitment moves that problem to the present by forcing the kernel
to find backing for all those pages during the fork(), and that takes time.

In any case, did you notice in the original posting that this 1 second
pause occurs on a system with 8GB of RAM?

That is apparently how long it takes for the kernel on his system to
find backing for all those pages. I suspect that delay is why
overcommitment is on by default.

S

 

[Jens Thoms Toerring]

Kaz, sorry for the "[OT]" but I prefer it that way;-)

That is apparently how long it takes for the kernel on his system to
find backing for all those pages. I suspect that delay is why
overcommitment is on by default.

I now see what you meant in you're earlier post, but - as a
completely unscientific experiment - switching off overcom-
mitment doesn't seem to make any difference on my system.
The (admittedly short and thus a bit dubious) times seem to
stay more or less exactly what they were before (i.e. about
15 ms when initializing the memory and 2.5 ms without). I'm
also still a bit puzzled why it could take the kernel nearly
1 second to find backing store on the system the OP seems to
have - I don't know the clock speed, but it seems to have
amounts of memory similar to mine (both 8 GB) and even a
newer CPU (Intel i7 versus "only" an i5 here). Of course,
this all could also be due to differences in the kernel ver-
sions used...
Best regards, Jens

 

[Kaz Kylheku]

Kaz, sorry for the "[OT]" but I prefer it that way;-)

That is apparently how long it takes for the kernel on his system to
find backing for all those pages. I suspect that delay is why
overcommitment is on by default.

I now see what you meant in you're earlier post, but - as a
completely unscientific experiment - switching off overcom-
mitment doesn't seem to make any difference on my system.

Finding backing for pages happens during the memset operation, whereas what is
being timed is the call to system().

Even with strict accounting, fork should not be duplicating the pages and
committing memory for them, but be implementing a copy-on-write optimization.
Strict accounting would mean that fork should fail if creating the (empty!)
maps for the process would bring the total VM footprint of the system over the
limit.

That's the theory.

Where that 1 second is being spent is anyone's guess. Maybe
that kernel has a patch that causes fork not to do copy-on-write.

I would start by running the test case using
"strace -f -r <command>" (with -f to follow forks
and -r to print relative timestamps).

This will reveal which syste call(s) are spending that time.

system() is not a system call, but pretty complicated function
which does a fork, exec and wait and probably mucking around
with file descriptors and probably signal handling and such.

 

[Stephen Sprunk]

Kaz, sorry for the "[OT]" but I prefer it that way;-)

In any case, did you notice in the original posting that this 1 second
pause occurs on a system with 8GB of RAM?

That is apparently how long it takes for the kernel on his system to
find backing for all those pages. I suspect that delay is why
overcommitment is on by default.

I now see what you meant in you're earlier post, but - as a
completely unscientific experiment - switching off overcom-
mitment doesn't seem to make any difference on my system.

Finding backing for pages happens during the memset operation, whereas
what is being timed is the call to system().

Even with strict accounting, fork should not be duplicating the pages and
committing memory for them, but be implementing a copy-on-write optimization.
Strict accounting would mean that fork should fail if creating the (empty!)
maps for the process would bring the total VM footprint of the system over the
limit.

That's the theory.

If you don't back those pages during the fork() operation, then you're
back to the original problem.

For instance, imagine a process that allocates a thousand pages. If
overcommitment is disabled, then the kernel will actually back them (or
allocation will fail). The process forks, and then both parent and
child write to each of the thousand pages, triggering a thousand
copy-on-writes and the need to find a thousand backing pages. If even
one of those pages can't be backed, then one of the processes will
fail--something that should have been impossible. (Or worse, the OOM
Killer turns its attention elsewhere to obtain backing pages...)

A simpler implementation would be to reject copy-on-write entirely,
duplicating the pages. However, that would unnecessarily double the
number of active pages and pollute the cache even if no writes occur,
which is the normal case.

S

 

[Stephen Sprunk]

Maybe I misunderstand what you mean by "duplicate", but it seems to me you
don't need to reject copy-on-write. You just need to reserve the number of
pages needed to do any future copying. You could do this with simple
counters: # of pages in use, # of pages reserved.

Right, that's the smart implementation: reserve the backing pages at the
time the process fork()s, but leave both of them pointing at the same
actual page until one of them changes it--at which point the page is
copied to one of the reserved pages.

The dumb implementation would be to copy every page at the time of
fork(), which removes the need to track reserved pages and to worry
about copy-on-write.

Both take more time and effort than deferring backing them until a
copy-on-write actually happens.

Like Ken, I also think that the bogeyman here--of processes which allocate a
ton of memory upfront--is a poor excuse and overhyped. Those applications
are few and far between. Sometimes important, maybe, but theoretically
easily fixed.

My Firefox is eating 807MB right now, and it spawns new processes now
and then. Overcommitment means the OS doesn't need to back those 202k
pages during the fork() call--copies which would be trashed a few cycles
after fork() returns when the child process calls exec().

It's not just about malloc() or mmap(); those problems are simpler to
explain, though tougher to justify.

S

 

[Nobody]

Disabling overcommitment moves that problem to the present by forcing
the kernel to find backing for all those pages during the fork(), and
that takes time.

Why would it take time? Obviously it takes _some_ time, but there's no
need for it to take significant time. It only has to check that the number
of shared (copy-on-write) pages is less than the number of uncommitted
pages, then subtract the former from the latter. It doesn't have to
actually do anything with those pages.

 

[Elmar]

Kaz, sorry for the "[OT]" but I prefer it that way;-)

That is apparently how long it takes for the kernel on his system to
find backing for all those pages. I suspect that delay is why
overcommitment is on by default.

I now see what you meant in you're earlier post, but - as a
completely unscientific experiment - switching off overcom-
mitment doesn't seem to make any difference on my system.
The (admittedly short and thus a bit dubious) times seem to
stay more or less exactly what they were before (i.e. about
15 ms when initializing the memory and 2.5 ms without). I'm
also still a bit puzzled why it could take the kernel nearly
1 second to find backing store on the system the OP seems to
have - I don't know the clock speed, but it seems to have
amounts of memory similar to mine (both 8 GB) and even a
newer CPU (Intel i7 versus "only" an i5 here). Of course,
this all could also be due to differences in the kernel ver-
sions used...

First of all, sorry to everyone who complained about my sub-optimal
choice of usenet group. I only ended up here because Google found the
previous thread on fork() and overcommit in this group.

BTW, the overcommit setting at my mysteriously slow fork() Core i7
machine is the default 0:

more /proc/sys/vm/overcommit_memory
0

Also, Kaz Kylheku was right: I was premature to blame the kernel. I
now upgraded to the latest CentOS Kernel 2.6.18-274.12.1.el5 (problem
persists), and installed the same Linux distro on another machine, but
everything was fine there.

So we now got same Linux Distro, same kernel 2.6.18-274.12.1.el5 #1
SMP Tue Nov 29 13:37:46 EST 2011 x86_64, and..

Core i7, 2.8GHz, 8GB RAM/20GB Swap: slow fork()
Opteron 1.8GHz, 2GB RAM/4GB Swap: fast fork()

I also shut down the X-server, since the Core i7 uses nVIDIA's
proprietary driver, and the Opteron AMD's proprietary driver. But the
Core i7 forks equally slow at runlevel 3.

Kaz Kylheku also suggested to use 'strace -f -r', which I did
(attached at the end for the slow forker).
Comparison between the slow and the fast forker shows that 'mmap' is
to be blamed (even without the timing info, one sees the output hang
at mmap for a second).

slow with memset:

0.000571 mmap(NULL, 524292096, PROT_READ|PROT_WRITE, MAP_PRIVATE|
MAP_ANONYMOUS, -1, 0) = 0x2b86fb5cc000
1.631431 rt_sigaction(SIGINT, {0x1, [], SA_RESTORER,
0x348a2302d0}, {SIG_DFL, [], 0}, 8) = 0

fast without memset:

0.000595 mmap(NULL, 524292096, PROT_READ|PROT_WRITE, MAP_PRIVATE|
MAP_ANONYMOUS, -1, 0) = 0x2b0bb57a4000
0.000194 rt_sigaction(SIGINT, {0x1, [], SA_RESTORER,
0x348a2302d0}, {SIG_DFL, [], 0}, 8) = 0

Complete output:

$ strace -f -r a.out
0.000000 execve("./a.out", ["a.out"], [/* 49 vars */]) = 0
0.001729 brk(0) = 0xf699000
0.000222 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|
MAP_ANONYMOUS, -1, 0) = 0x2b86fb59b000
0.000323 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|
MAP_ANONYMOUS, -1, 0) = 0x2b86fb59c000
0.000190 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such
file or directory)
0.000333 open("/etc/ld.so.cache", O_RDONLY) = 3
0.000157 fstat(3, {st_mode=S_IFREG|0644, st_size=187712, ...}) =
0
0.000280 mmap(NULL, 187712, PROT_READ, MAP_PRIVATE, 3, 0) =
0x2b86fb59d000
0.000165 close(3) = 0
0.000251 open("/lib64/libc.so.6", O_RDONLY) = 3
0.000136 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>
\0\1\0\0\0\220\332!\2124\0\0\0"..., 832) = 832
0.000211 fstat(3, {st_mode=S_IFREG|0755, st_size=1722304, ...}) =
0
0.000372 mmap(0x348a200000, 3502424, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x348a200000
0.000120 mprotect(0x348a34e000, 2097152, PROT_NONE) = 0
0.000134 mmap(0x348a54e000, 20480, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x14e000) = 0x348a54e000
0.000255 mmap(0x348a553000, 16728, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x348a553000
0.000169 close(3) = 0
0.000184 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|
MAP_ANONYMOUS, -1, 0) = 0x2b86fb5cb000
0.000182 arch_prctl(ARCH_SET_FS, 0x2b86fb5cb6e0) = 0
0.000459 mprotect(0x348a54e000, 16384, PROT_READ) = 0
0.000141 mprotect(0x348a01c000, 4096, PROT_READ) = 0
0.000146 munmap(0x2b86fb59d000, 187712) = 0
0.000571 mmap(NULL, 524292096, PROT_READ|PROT_WRITE, MAP_PRIVATE|
MAP_ANONYMOUS, -1, 0) = 0x2b86fb5cc000
1.631431 rt_sigaction(SIGINT, {0x1, [], SA_RESTORER,
0x348a2302d0}, {SIG_DFL, [], 0}, 8) = 0
0.000381 rt_sigaction(SIGQUIT, {0x1, [], SA_RESTORER,
0x348a2302d0}, {SIG_DFL, [], 0}, 8) = 0
0.000212 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
0.000122 clone(Process 25300 attached (waiting for parent)
Process 25300 resumed (parent 25263 ready)
child_stack=0, flags=CLONE_PARENT_SETTID|SIGCHLD,
parent_tidptr=0x7fff8ab7c538) = 25300
[pid 25300] 0.436593 rt_sigaction(SIGINT, {SIG_DFL, [],
SA_RESTORER, 0x348a2302d0}, <unfinished ...>
[pid 25263] 0.000055 wait4(25300, Process 25263 suspended
<unfinished ...>
[pid 25300] 0.000009 <... rt_sigaction resumed> NULL, 8) = 0
[pid 25300] 0.000020 rt_sigaction(SIGQUIT, {SIG_DFL, [],
SA_RESTORER, 0x348a2302d0}, NULL, 8) = 0
[pid 25300] 0.000063 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 25300] 0.000072 execve("/bin/sh", ["sh", "-c", "ls Hello"],
[/* 49 vars */]) = 0
[pid 25300] 0.451537 brk(0) = 0xfde2000
[pid 25300] 0.000114 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b228a067000
[pid 25300] 0.000140 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b228a068000
[pid 25300] 0.000061 access("/etc/ld.so.preload", R_OK) = -1
ENOENT (No such file or directory)
[pid 25300] 0.000129 open("/etc/ld.so.cache", O_RDONLY) = 3
[pid 25300] 0.000050 fstat(3, {st_mode=S_IFREG|0644,
st_size=187712, ...}) = 0
[pid 25300] 0.000177 mmap(NULL, 187712, PROT_READ, MAP_PRIVATE,
3, 0) = 0x2b228a069000
[pid 25300] 0.000055 close(3) = 0
[pid 25300] 0.000162 open("/lib64/libtermcap.so.2", O_RDONLY) = 3
[pid 25300] 0.000073 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>
\0\1\0\0\0@\17\240\2154\0\0\0"..., 832) = 832
[pid 25300] 0.000090 fstat(3, {st_mode=S_IFREG|0755,
st_size=15584, ...}) = 0
[pid 25300] 0.000186 mmap(0x348da00000, 2108688, PROT_READ|
PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x348da00000
[pid 25300] 0.000052 mprotect(0x348da03000, 2093056, PROT_NONE) =
0
[pid 25300] 0.000056 mmap(0x348dc02000, 4096, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) =
0x348dc02000
[pid 25300] 0.000089 close(3) = 0
[pid 25300] 0.000125 open("/lib64/libdl.so.2", O_RDONLY) = 3
[pid 25300] 0.000063 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>
\0\1\0\0\0\20\16\240\2124\0\0\0"..., 832) = 832
[pid 25300] 0.000079 fstat(3, {st_mode=S_IFREG|0755,
st_size=23360, ...}) = 0
[pid 25300] 0.000172 mmap(0x348aa00000, 2109696, PROT_READ|
PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x348aa00000
[pid 25300] 0.000042 mprotect(0x348aa02000, 2097152, PROT_NONE) =
0
[pid 25300] 0.000032 mmap(0x348ac02000, 8192, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) =
0x348ac02000
[pid 25300] 0.000071 close(3) = 0
[pid 25300] 0.000098 open("/lib64/libc.so.6", O_RDONLY) = 3
[pid 25300] 0.000058 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>
\0\1\0\0\0\220\332!\2124\0\0\0"..., 832) = 832
[pid 25300] 0.000094 fstat(3, {st_mode=S_IFREG|0755,
st_size=1722304, ...}) = 0
[pid 25300] 0.000180 mmap(0x348a200000, 3502424, PROT_READ|
PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x348a200000
[pid 25300] 0.000034 mprotect(0x348a34e000, 2097152, PROT_NONE) =
0
[pid 25300] 0.000051 mmap(0x348a54e000, 20480, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x14e000) =
0x348a54e000
[pid 25300] 0.000065 mmap(0x348a553000, 16728, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x348a553000
[pid 25300] 0.000065 close(3) = 0
[pid 25300] 0.000084 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b228a097000
[pid 25300] 0.000104 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b228a098000
[pid 25300] 0.000035 arch_prctl(ARCH_SET_FS, 0x2b228a097f50) = 0
[pid 25300] 0.000078 mprotect(0x348ac02000, 4096, PROT_READ) = 0
[pid 25300] 0.000030 mprotect(0x348a54e000, 16384, PROT_READ) = 0
[pid 25300] 0.000044 mprotect(0x348a01c000, 4096, PROT_READ) = 0
[pid 25300] 0.000076 munmap(0x2b228a069000, 187712) = 0
[pid 25300] 0.000409 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
[pid 25300] 0.000063 open("/dev/tty", O_RDWR|O_NONBLOCK) = 3
[pid 25300] 0.000067 close(3) = 0
[pid 25300] 0.000557 brk(0) = 0xfde2000
[pid 25300] 0.000045 brk(0xfe03000) = 0xfe03000
[pid 25300] 0.000091 open("/usr/lib/locale/locale-archive",
O_RDONLY) = 3
[pid 25300] 0.000105 fstat(3, {st_mode=S_IFREG|0644,
st_size=56426032, ...}) = 0
[pid 25300] 0.000171 mmap(NULL, 56426032, PROT_READ, MAP_PRIVATE,
3, 0) = 0x2b228a099000
[pid 25300] 0.000054 close(3) = 0
[pid 25300] 0.000220 getuid() = 500
[pid 25300] 0.000031 getgid() = 500
[pid 25300] 0.000034 geteuid() = 500
[pid 25300] 0.000038 getegid() = 500
[pid 25300] 0.000088 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
[pid 25300] 0.000316 open("/proc/meminfo", O_RDONLY) = 3
[pid 25300] 0.000168 fstat(3, {st_mode=S_IFREG|0444,
st_size=0, ...}) = 0
[pid 25300] 0.000165 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b228d669000
[pid 25300] 0.000062 read(3, "MemTotal: 8168624 kB
\nMemFre"..., 1024) = 777
[pid 25300] 0.000235 close(3) = 0
[pid 25300] 0.000043 munmap(0x2b228d669000, 4096) = 0
[pid 25300] 0.000217 rt_sigaction(SIGCHLD, {SIG_DFL, [],
SA_RESTORER, 0x348a2302d0}, {SIG_DFL, [], 0}, 8) = 0
[pid 25300] 0.000099 rt_sigaction(SIGCHLD, {SIG_DFL, [],
SA_RESTORER, 0x348a2302d0}, {SIG_DFL, [], SA_RESTORER, 0x348a2302d0},
8) = 0
[pid 25300] 0.000121 rt_sigaction(SIGINT, {SIG_DFL, [],
SA_RESTORER, 0x348a2302d0}, {SIG_DFL, [], 0}, 8) = 0
[pid 25300] 0.000100 rt_sigaction(SIGINT, {SIG_DFL, [],
SA_RESTORER, 0x348a2302d0}, {SIG_DFL, [], SA_RESTORER, 0x348a2302d0},
8) = 0
[pid 25300] 0.000111 rt_sigaction(SIGQUIT, {SIG_DFL, [],
SA_RESTORER, 0x348a2302d0}, {SIG_DFL, [], 0}, 8) = 0
[pid 25300] 0.000096 rt_sigaction(SIGQUIT, {SIG_DFL, [],
SA_RESTORER, 0x348a2302d0}, {SIG_DFL, [], SA_RESTORER, 0x348a2302d0},
8) = 0
[pid 25300] 0.000098 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
[pid 25300] 0.000044 rt_sigaction(SIGQUIT, {0x1, [], SA_RESTORER,
0x348a2302d0}, {SIG_DFL, [], SA_RESTORER, 0x348a2302d0}, 8) = 0
[pid 25300] 0.000122 uname({sys="Linux", node="yasara3", ...}) =
0
[pid 25300] 0.000551 stat("/home/elmar/python", {st_mode=S_IFDIR|
0777, st_size=36864, ...}) = 0
[pid 25300] 0.000183 stat(".", {st_mode=S_IFDIR|0777,
st_size=36864, ...}) = 0
[pid 25300] 0.000178 getpid() = 25300
[pid 25300] 0.000115 open("/usr/lib64/gconv/gconv-modules.cache",
O_RDONLY) = 3
[pid 25300] 0.000103 fstat(3, {st_mode=S_IFREG|0644,
st_size=25464, ...}) = 0
[pid 25300] 0.000157 mmap(NULL, 25464, PROT_READ, MAP_SHARED, 3,
0) = 0x2b228d669000
[pid 25300] 0.000049 close(3) = 0
[pid 25300] 0.000136 getppid() = 25263
[pid 25300] 0.000071 stat(".", {st_mode=S_IFDIR|0777,
st_size=36864, ...}) = 0
[pid 25300] 0.000198 stat("/usr/kerberos/sbin/sh",
0x7fff8049aef0) = -1 ENOENT (No such file or directory)
[pid 25300] 0.000078 stat("/usr/kerberos/bin/sh", 0x7fff8049aef0)
= -1 ENOENT (No such file or directory)
[pid 25300] 0.000062 stat("/usr/local/bin/sh", 0x7fff8049aef0) =
-1 ENOENT (No such file or directory)
[pid 25300] 0.000069 stat("/usr/bin/sh", 0x7fff8049aef0) = -1
ENOENT (No such file or directory)
[pid 25300] 0.000073 stat("/bin/sh", {st_mode=S_IFREG|0755,
st_size=801528, ...}) = 0
[pid 25300] 0.000161 access("/bin/sh", X_OK) = 0
[pid 25300] 0.000053 access("/bin/sh", R_OK) = 0
[pid 25300] 0.000042 stat("/bin/sh", {st_mode=S_IFREG|0755,
st_size=801528, ...}) = 0
[pid 25300] 0.000165 access("/bin/sh", X_OK) = 0
[pid 25300] 0.000053 access("/bin/sh", R_OK) = 0
[pid 25300] 0.000177 getpgrp() = 25262
[pid 25300] 0.000042 rt_sigaction(SIGCHLD, {0x436360, [],
SA_RESTORER, 0x348a2302d0}, {SIG_DFL, [], SA_RESTORER, 0x348a2302d0},
8) = 0
[pid 25300] 0.000407 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
[pid 25300] 0.000050 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
[pid 25300] 0.000104 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
[pid 25300] 0.000289 stat(".", {st_mode=S_IFDIR|0777,
st_size=36864, ...}) = 0
[pid 25300] 0.000179 stat("/usr/kerberos/sbin/ls",
0x7fff8049adb0) = -1 ENOENT (No such file or directory)
[pid 25300] 0.000064 stat("/usr/kerberos/bin/ls", 0x7fff8049adb0)
= -1 ENOENT (No such file or directory)
[pid 25300] 0.000072 stat("/usr/local/bin/ls", 0x7fff8049adb0) =
-1 ENOENT (No such file or directory)
[pid 25300] 0.000062 stat("/usr/bin/ls", 0x7fff8049adb0) = -1
ENOENT (No such file or directory)
[pid 25300] 0.000051 stat("/bin/ls", {st_mode=S_IFREG|0755,
st_size=91272, ...}) = 0
[pid 25300] 0.000190 access("/bin/ls", X_OK) = 0
[pid 25300] 0.000032 access("/bin/ls", R_OK) = 0
[pid 25300] 0.000036 stat("/bin/ls", {st_mode=S_IFREG|0755,
st_size=91272, ...}) = 0
[pid 25300] 0.000179 access("/bin/ls", X_OK) = 0
[pid 25300] 0.000042 access("/bin/ls", R_OK) = 0
[pid 25300] 0.000049 rt_sigaction(SIGINT, {SIG_DFL, [],
SA_RESTORER, 0x348a2302d0}, {SIG_DFL, [], SA_RESTORER, 0x348a2302d0},
8) = 0
[pid 25300] 0.000108 rt_sigaction(SIGQUIT, {SIG_DFL, [],
SA_RESTORER, 0x348a2302d0}, {0x1, [], SA_RESTORER, 0x348a2302d0}, 8) =
0
[pid 25300] 0.000105 rt_sigaction(SIGCHLD, {SIG_DFL, [],
SA_RESTORER, 0x348a2302d0}, {0x436360, [], SA_RESTORER, 0x348a2302d0},
8) = 0
[pid 25300] 0.000110 execve("/bin/ls", ["ls", "Hello"], [/* 48
vars */]) = 0
[pid 25300] 0.002655 brk(0) = 0x3052000
[pid 25300] 0.000086 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af0fbafe000
[pid 25300] 0.000153 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af0fbaff000
[pid 25300] 0.000068 access("/etc/ld.so.preload", R_OK) = -1
ENOENT (No such file or directory)
[pid 25300] 0.000108 open("/etc/ld.so.cache", O_RDONLY) = 3
[pid 25300] 0.000059 fstat(3, {st_mode=S_IFREG|0644,
st_size=187712, ...}) = 0
[pid 25300] 0.000238 mmap(NULL, 187712, PROT_READ, MAP_PRIVATE,
3, 0) = 0x2af0fbb00000
[pid 25300] 0.000037 close(3) = 0
[pid 25300] 0.000169 open("/lib64/librt.so.1", O_RDONLY) = 3
[pid 25300] 0.000061 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>
\0\1\0\0\0 \"\240\2164\0\0\0"..., 832) = 832
[pid 25300] 0.000077 fstat(3, {st_mode=S_IFREG|0755,
st_size=53448, ...}) = 0
[pid 25300] 0.000158 mmap(0x348ea00000, 2132936, PROT_READ|
PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x348ea00000
[pid 25300] 0.000044 mprotect(0x348ea07000, 2097152, PROT_NONE) =
0
[pid 25300] 0.000042 mmap(0x348ec07000, 8192, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) =
0x348ec07000
[pid 25300] 0.000131 close(3) = 0
[pid 25300] 0.000139 open("/lib64/libacl.so.1", O_RDONLY) = 3
[pid 25300] 0.000059 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>
\0\1\0\0\0\240\30@\2234\0\0\0"..., 832) = 832
[pid 25300] 0.000080 fstat(3, {st_mode=S_IFREG|0755,
st_size=27920, ...}) = 0
[pid 25300] 0.000156 mmap(0x3493400000, 2120904, PROT_READ|
PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3493400000
[pid 25300] 0.000041 mprotect(0x3493406000, 2093056, PROT_NONE) =
0
[pid 25300] 0.000036 mmap(0x3493605000, 4096, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5000) =
0x3493605000
[pid 25300] 0.000062 close(3) = 0
[pid 25300] 0.000052 open("/lib64/libselinux.so.1", O_RDONLY) = 3
[pid 25300] 0.000061 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>
\0\1\0\0\0\340E`\2214\0\0\0"..., 832) = 832
[pid 25300] 0.000066 fstat(3, {st_mode=S_IFREG|0755,
st_size=95464, ...}) = 0
[pid 25300] 0.000185 mmap(0x3491600000, 2192800, PROT_READ|
PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3491600000
[pid 25300] 0.000041 mprotect(0x3491615000, 2097152, PROT_NONE) =
0
[pid 25300] 0.000030 mmap(0x3491815000, 8192, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) =
0x3491815000
[pid 25300] 0.000076 mmap(0x3491817000, 1440, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3491817000
[pid 25300] 0.000063 close(3) = 0
[pid 25300] 0.000081 open("/lib64/libc.so.6", O_RDONLY) = 3
[pid 25300] 0.000066 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>
\0\1\0\0\0\220\332!\2124\0\0\0"..., 832) = 832
[pid 25300] 0.000078 fstat(3, {st_mode=S_IFREG|0755,
st_size=1722304, ...}) = 0
[pid 25300] 0.000160 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af0fbb2e000
[pid 25300] 0.000047 mmap(0x348a200000, 3502424, PROT_READ|
PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x348a200000
[pid 25300] 0.000041 mprotect(0x348a34e000, 2097152, PROT_NONE) =
0
[pid 25300] 0.000030 mmap(0x348a54e000, 20480, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x14e000) =
0x348a54e000
[pid 25300] 0.000081 mmap(0x348a553000, 16728, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x348a553000
[pid 25300] 0.000061 close(3) = 0
[pid 25300] 0.000080 open("/lib64/libpthread.so.0", O_RDONLY) = 3
[pid 25300] 0.000073 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>
\0\1\0\0\0\240W\340\2124\0\0\0"..., 832) = 832
[pid 25300] 0.000084 fstat(3, {st_mode=S_IFREG|0755,
st_size=145824, ...}) = 0
[pid 25300] 0.000155 mmap(0x348ae00000, 2204528, PROT_READ|
PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x348ae00000
[pid 25300] 0.000041 mprotect(0x348ae16000, 2093056, PROT_NONE) =
0
[pid 25300] 0.000032 mmap(0x348b015000, 8192, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) =
0x348b015000
[pid 25300] 0.000058 mmap(0x348b017000, 13168, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x348b017000
[pid 25300] 0.000063 close(3) = 0
[pid 25300] 0.000073 open("/lib64/libattr.so.1", O_RDONLY) = 3
[pid 25300] 0.000088 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>
\0\1\0\0\0\320\17\300\2254\0\0\0"..., 832) = 832
[pid 25300] 0.000085 fstat(3, {st_mode=S_IFREG|0755,
st_size=17888, ...}) = 0
[pid 25300] 0.000155 mmap(0x3495c00000, 2110728, PROT_READ|
PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3495c00000
[pid 25300] 0.000030 mprotect(0x3495c04000, 2093056, PROT_NONE) =
0
[pid 25300] 0.000042 mmap(0x3495e03000, 4096, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) =
0x3495e03000
[pid 25300] 0.000066 close(3) = 0
[pid 25300] 0.000109 open("/lib64/libdl.so.2", O_RDONLY) = 3
[pid 25300] 0.000075 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>
\0\1\0\0\0\20\16\240\2124\0\0\0"..., 832) = 832
[pid 25300] 0.000070 fstat(3, {st_mode=S_IFREG|0755,
st_size=23360, ...}) = 0
[pid 25300] 0.000156 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af0fbb2f000
[pid 25300] 0.000045 mmap(0x348aa00000, 2109696, PROT_READ|
PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x348aa00000
[pid 25300] 0.000042 mprotect(0x348aa02000, 2097152, PROT_NONE) =
0
[pid 25300] 0.000030 mmap(0x348ac02000, 8192, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) =
0x348ac02000
[pid 25300] 0.000094 close(3) = 0
[pid 25300] 0.000050 open("/lib64/libsepol.so.1", O_RDONLY) = 3
[pid 25300] 0.000054 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>
\0\1\0\0\0@= \2214\0\0\0"..., 832) = 832
[pid 25300] 0.000074 fstat(3, {st_mode=S_IFREG|0755,
st_size=247496, ...}) = 0
[pid 25300] 0.000168 mmap(0x3491200000, 2383168, PROT_READ|
PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3491200000
[pid 25300] 0.000043 mprotect(0x349123b000, 2097152, PROT_NONE) =
0
[pid 25300] 0.000036 mmap(0x349143b000, 4096, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3b000) =
0x349143b000
[pid 25300] 0.000099 mmap(0x349143c000, 40256, PROT_READ|
PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x349143c000
[pid 25300] 0.000048 close(3) = 0
[pid 25300] 0.000134 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af0fbb30000
[pid 25300] 0.000070 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af0fbb31000
[pid 25300] 0.000045 arch_prctl(ARCH_SET_FS, 0x2af0fbb30e20) = 0
[pid 25300] 0.000130 mprotect(0x348ec07000, 4096, PROT_READ) = 0
[pid 25300] 0.000036 mprotect(0x348a54e000, 16384, PROT_READ) = 0
[pid 25300] 0.000028 mprotect(0x348b015000, 4096, PROT_READ) = 0
[pid 25300] 0.000037 mprotect(0x348a01c000, 4096, PROT_READ) = 0
[pid 25300] 0.000037 mprotect(0x348ac02000, 4096, PROT_READ) = 0
[pid 25300] 0.000056 munmap(0x2af0fbb00000, 187712) = 0
[pid 25300] 0.000281 set_tid_address(0x2af0fbb30eb0) = 25300
[pid 25300] 0.000020 set_robust_list(0x2af0fbb30ec0, 0x18) = 0
[pid 25300] 0.000026 futex(0x7fff2b1bab2c, FUTEX_WAKE_PRIVATE, 1)
= 0
[pid 25300] 0.000107 rt_sigaction(SIGRTMIN, {0x348ae05380, [],
SA_RESTORER|SA_SIGINFO, 0x348ae0eb70}, NULL, 8) = 0
[pid 25300] 0.000075 rt_sigaction(SIGRT_1, {0x348ae052b0, [],
SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x348ae0eb70}, NULL, 8) = 0
[pid 25300] 0.000074 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1],
NULL, 8) = 0
[pid 25300] 0.000061 getrlimit(RLIMIT_STACK,
{rlim_cur=10240*1024, rlim_max=RLIM_INFINITY}) = 0
[pid 25300] 0.000312 access("/etc/selinux/", F_OK) = 0
[pid 25300] 0.000431 brk(0) = 0x3052000
[pid 25300] 0.000045 brk(0x3073000) = 0x3073000
[pid 25300] 0.000086 open("/etc/selinux/config", O_RDONLY) = 3
[pid 25300] 0.000151 fstat(3, {st_mode=S_IFREG|0644,
st_size=511, ...}) = 0
[pid 25300] 0.000167 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af0fbb00000
[pid 25300] 0.000033 read(3, "# This file controls the state
o"..., 4096) = 511
[pid 25300] 0.000151 read(3, "", 4096) = 0
[pid 25300] 0.000055 close(3) = 0
[pid 25300] 0.000033 munmap(0x2af0fbb00000, 4096) = 0
[pid 25300] 0.000226 open("/proc/mounts", O_RDONLY) = 3
[pid 25300] 0.000163 fstat(3, {st_mode=S_IFREG|0444,
st_size=0, ...}) = 0
[pid 25300] 0.000159 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af0fbb00000
[pid 25300] 0.000033 read(3, "rootfs / rootfs rw 0 0\n/dev/
root"..., 1024) = 546
[pid 25300] 0.000114 read(3, "", 1024) = 0
[pid 25300] 0.000026 close(3) = 0
[pid 25300] 0.000041 munmap(0x2af0fbb00000, 4096) = 0
[pid 25300] 0.000296 open("/usr/lib/locale/locale-archive",
O_RDONLY) = 3
[pid 25300] 0.000084 fstat(3, {st_mode=S_IFREG|0644,
st_size=56426032, ...}) = 0
[pid 25300] 0.000156 mmap(NULL, 56426032, PROT_READ, MAP_PRIVATE,
3, 0) = 0x2af0fbb32000
[pid 25300] 0.000060 close(3) = 0
[pid 25300] 0.000206 ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS,
{B38400 opost isig icanon echo ...}) = 0
[pid 25300] 0.000160 ioctl(1, TIOCGWINSZ, {ws_row=25, ws_col=80,
ws_xpixel=0, ws_ypixel=0}) = 0
[pid 25300] 0.000127 stat("Hello", 0x30535e8) = -1 ENOENT (No
such file or directory)
[pid 25300] 0.000044 lstat("Hello", 0x30535e8) = -1 ENOENT (No
such file or directory)
[pid 25300] 0.000112 write(2, "ls: ", 4ls: ) = 4
[pid 25300] 0.000051 write(2, "Hello", 5Hello) = 5
[pid 25300] 0.000097 open("/usr/share/locale/locale.alias",
O_RDONLY) = 3
[pid 25300] 0.000080 fstat(3, {st_mode=S_IFREG|0644,
st_size=2528, ...}) = 0
[pid 25300] 0.000196 mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af0ff102000
[pid 25300] 0.000029 read(3, "# Locale name alias data base.
\n#"..., 4096) = 2528
[pid 25300] 0.000160 read(3, "", 4096) = 0
[pid 25300] 0.000051 close(3) = 0
[pid 25300] 0.000034 munmap(0x2af0ff102000, 4096) = 0
[pid 25300] 0.000080 open("/usr/share/locale/en_US.UTF-8/
LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or
directory)
[pid 25300] 0.000095 open("/usr/share/locale/en_US.utf8/
LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or
directory)
[pid 25300] 0.000086 open("/usr/share/locale/en_US/LC_MESSAGES/
libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
[pid 25300] 0.000086 open("/usr/share/locale/en.UTF-8/LC_MESSAGES/
libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
[pid 25300] 0.000095 open("/usr/share/locale/en.utf8/LC_MESSAGES/
libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
[pid 25300] 0.000092 open("/usr/share/locale/en/LC_MESSAGES/
libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
[pid 25300] 0.000099 write(2, ": No such file or directory", 27:
No such file or directory) = 27
[pid 25300] 0.000054 write(2, "\n", 1
) = 1
[pid 25300] 0.000040 close(1) = 0
[pid 25300] 0.000057 exit_group(2) = ?
Process 25263 resumed
Process 25300 detached
0.001769 <... wait4 resumed> [{WIFEXITED(s) && WEXITSTATUS(s) ==
2}], 0, NULL) = 25300
0.000055 rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER,
0x348a2302d0}, NULL, 8) = 0
0.000086 rt_sigaction(SIGQUIT, {SIG_DFL, [], SA_RESTORER,
0x348a2302d0}, NULL, 8) = 0
0.000064 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
0.000033 --- SIGCHLD (Child exited) @ 0 (0) ---
0.000131 fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(136,
24), ...}) = 0
0.000162 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|
MAP_ANONYMOUS, -1, 0) = 0x2b871a9cd000
0.000141 write(1, "Time before: 1326320210.213833\n", 31Time
before: 1326320210.213833
) = 31
0.000081 write(1, "Time after: 1326320211.131237\n", 31Time
after: 1326320211.131237
) = 31
0.000088 exit_group(31) = ?


Nasty, nasty ;-)

CU,
Elmar