runsolver Copyright (C) 2010 Olivier ROUSSEL

This is runsolver version 3.2.9a (svn: 651)

This program 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 General Public License for more details.

command line: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012061533/gj-paranoid-solver-0.1/rand316.sarge.cudf.sarge.log.runsolver ./gj-paranoid-solver-0.1 /home/misc2010/data/icse/sarge/rand316.sarge.cudf /home/misc2010/tmp/201012061533/gj-paranoid-solver-0.1/rand316.sarge.cudf.sarge.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 seconds
Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB
Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.47 1.20 1.11 5/46 12277
/proc/meminfo: memFree=782424/1048576 swapFree=2078820/2097144
[pid=12275] ppid=12274 vsize=2568 CPUtime=0
/proc/12275/stat : 12275 (gj-paranoid-sol) S 12274 12275 2059 34821 2220 4202496 373 0 0 0 0 0 0 0 18 0 1 0 875329102 2629632 271 1283457024 134512640 135304128 4294099264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12275/statm: 642 271 232 194 0 28 0
[pid=12276] ppid=12275 vsize=11244 CPUtime=0
/proc/12276/stat : 12276 (java) R 12275 12275 2059 34821 2220 4202496 910 0 0 0 0 0 0 0 25 0 2 0 875329102 11513856 643 1283457024 134512640 134550932 4292341488 18446744073709551615 4159455480 0 0 0 0 18446744073709551615 0 0 17 0 0 0 0
/proc/12276/statm: 2811 643 285 10 0 1185 0
[pid=12276/tid=12277] ppid=12275 vsize=11244 CPUtime=0
/proc/12276/task/12277/stat : 12277 (java) R 12275 12275 2059 34821 2220 4202560 0 0 0 0 0 0 0 0 25 0 2 0 875329103 11513856 643 1283457024 134512640 134550932 4292341488 18446744073709551615 4159455480 0 0 0 0 0 0 0 -1 0 0 0 0

[startup+0.125327 s]
/proc/loadavg: 1.47 1.20 1.11 5/46 12277
/proc/meminfo: memFree=782424/1048576 swapFree=2078820/2097144
[pid=12275] ppid=12274 vsize=2568 CPUtime=0
/proc/12275/stat : 12275 (gj-paranoid-sol) S 12274 12275 2059 34821 2220 4202496 373 0 0 0 0 0 0 0 18 0 1 0 875329102 2629632 271 1283457024 134512640 135304128 4294099264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12275/statm: 642 271 232 194 0 28 0
[pid=12276] ppid=12275 vsize=409996 CPUtime=0.12
/proc/12276/stat : 12276 (java) S 12275 12275 2059 34821 2220 4202496 4058 0 1 0 9 3 0 0 25 0 9 0 875329102 419835904 3522 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/12276/statm: 102499 3522 1875 10 0 96679 0
[pid=12276/tid=12277] ppid=12275 vsize=409996 CPUtime=0.1
/proc/12276/task/12277/stat : 12277 (java) R 12275 12275 2059 34821 2220 4202560 2863 0 1 0 8 2 0 0 25 0 9 0 875329103 419835904 3522 1283457024 134512640 134550932 4292341488 18446744073709551615 4114908039 0 4 0 16800975 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 412564

[startup+0.205338 s]
/proc/loadavg: 1.47 1.20 1.11 5/46 12277
/proc/meminfo: memFree=782424/1048576 swapFree=2078820/2097144
[pid=12275] ppid=12274 vsize=2568 CPUtime=0
/proc/12275/stat : 12275 (gj-paranoid-sol) S 12274 12275 2059 34821 2220 4202496 373 0 0 0 0 0 0 0 18 0 1 0 875329102 2629632 271 1283457024 134512640 135304128 4294099264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12275/statm: 642 271 232 194 0 28 0
[pid=12276] ppid=12275 vsize=410140 CPUtime=0.2
/proc/12276/stat : 12276 (java) S 12275 12275 2059 34821 2220 4202496 5194 0 1 0 17 3 0 0 25 0 9 0 875329102 419983360 4657 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/12276/statm: 102535 4657 1883 10 0 96715 0
[pid=12276/tid=12277] ppid=12275 vsize=410140 CPUtime=0.16
/proc/12276/task/12277/stat : 12277 (java) R 12275 12275 2059 34821 2220 4202560 3376 0 1 0 14 2 0 0 25 0 9 0 875329103 419983360 4657 1283457024 134512640 134550932 4292341488 18446744073709551615 4114934065 0 4 0 16800975 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 412708

[startup+0.305364 s]
/proc/loadavg: 1.47 1.20 1.11 5/46 12277
/proc/meminfo: memFree=782424/1048576 swapFree=2078820/2097144
[pid=12275] ppid=12274 vsize=2568 CPUtime=0
/proc/12275/stat : 12275 (gj-paranoid-sol) S 12274 12275 2059 34821 2220 4202496 373 0 0 0 0 0 0 0 18 0 1 0 875329102 2629632 271 1283457024 134512640 135304128 4294099264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12275/statm: 642 271 232 194 0 28 0
[pid=12276] ppid=12275 vsize=410140 CPUtime=0.3
/proc/12276/stat : 12276 (java) S 12275 12275 2059 34821 2220 4202496 5969 0 1 0 26 4 0 0 25 0 9 0 875329102 419983360 5432 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/12276/statm: 102535 5432 1883 10 0 96715 0
[pid=12276/tid=12277] ppid=12275 vsize=410140 CPUtime=0.25
/proc/12276/task/12277/stat : 12277 (java) R 12275 12275 2059 34821 2220 4202560 3377 0 1 0 23 2 0 0 25 0 9 0 875329103 419983360 5432 1283457024 134512640 134550932 4292341488 18446744073709551615 4153583830 0 4 0 16800975 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 412708

[startup+0.705474 s]
/proc/loadavg: 1.47 1.20 1.11 5/46 12277
/proc/meminfo: memFree=782424/1048576 swapFree=2078820/2097144
[pid=12275] ppid=12274 vsize=2568 CPUtime=0
/proc/12275/stat : 12275 (gj-paranoid-sol) S 12274 12275 2059 34821 2220 4202496 373 0 0 0 0 0 0 0 18 0 1 0 875329102 2629632 271 1283457024 134512640 135304128 4294099264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12275/statm: 642 271 232 194 0 28 0
[pid=12276] ppid=12275 vsize=410740 CPUtime=0.7
/proc/12276/stat : 12276 (java) S 12275 12275 2059 34821 2220 4202496 12858 0 1 0 61 9 0 0 25 0 9 0 875329102 420597760 12143 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/12276/statm: 102685 12143 2879 10 0 96865 0
[pid=12276/tid=12277] ppid=12275 vsize=410740 CPUtime=0.39
/proc/12276/task/12277/stat : 12277 (java) R 12275 12275 2059 34821 2220 4202560 4067 0 1 0 36 3 0 0 25 0 9 0 875329103 420597760 12143 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 4 0 16800975 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 413308

Solver just ended. Dumping a history of the last processes samples

[startup+0.805489 s]
/proc/loadavg: 1.47 1.20 1.11 5/46 12277
/proc/meminfo: memFree=782424/1048576 swapFree=2078820/2097144
[pid=12275] ppid=12274 vsize=2568 CPUtime=0
/proc/12275/stat : 12275 (gj-paranoid-sol) S 12274 12275 2059 34821 2220 4202496 373 0 0 0 0 0 0 0 18 0 1 0 875329102 2629632 271 1283457024 134512640 135304128 4294099264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12275/statm: 642 271 232 194 0 28 0
[pid=12276] ppid=12275 vsize=410740 CPUtime=0.8
/proc/12276/stat : 12276 (java) S 12275 12275 2059 34821 2220 4202496 14720 0 1 0 71 9 0 0 25 0 9 0 875329102 420597760 14005 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/12276/statm: 102685 14005 2879 10 0 96865 0
[pid=12276/tid=12277] ppid=12275 vsize=410740 CPUtime=0.44
/proc/12276/task/12277/stat : 12277 (java) R 12275 12275 2059 34821 2220 4202560 5027 0 1 0 41 3 0 0 25 0 9 0 875329103 420597760 14005 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 4 0 16800975 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 0.8
Current children cumulated vsize (KiB) 413308

[startup+1.00553 s]
/proc/loadavg: 1.47 1.20 1.11 5/46 12277
/proc/meminfo: memFree=782424/1048576 swapFree=2078820/2097144
[pid=12275] ppid=12274 vsize=2568 CPUtime=0
/proc/12275/stat : 12275 (gj-paranoid-sol) S 12274 12275 2059 34821 2220 4202496 373 0 0 0 0 0 0 0 18 0 1 0 875329102 2629632 271 1283457024 134512640 135304128 4294099264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12275/statm: 642 271 232 194 0 28 0
[pid=12276] ppid=12275 vsize=410740 CPUtime=1
/proc/12276/stat : 12276 (java) S 12275 12275 2059 34821 2220 4202496 17660 0 1 0 89 11 0 0 25 0 9 0 875329102 420597760 16931 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/12276/statm: 102685 16931 2881 10 0 96865 0
[pid=12276/tid=12277] ppid=12275 vsize=410740 CPUtime=0.56
/proc/12276/task/12277/stat : 12277 (java) R 12275 12275 2059 34821 2220 4202560 5115 0 1 0 53 3 0 0 25 0 9 0 875329103 420597760 16931 1283457024 134512640 134550932 4292341488 18446744073709551615 4114935639 0 4 0 16800975 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 1
Current children cumulated vsize (KiB) 413308

[startup+1.10538 s]
/proc/loadavg: 1.52 1.22 1.12 1/54 12286
/proc/meminfo: memFree=727044/1048576 swapFree=2078820/2097144
[pid=12275] ppid=12274 vsize=2568 CPUtime=0
/proc/12275/stat : 12275 (gj-paranoid-sol) S 12274 12275 2059 34821 2220 4202496 373 0 0 0 0 0 0 0 18 0 1 0 875329102 2629632 271 1283457024 134512640 135304128 4294099264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12275/statm: 642 271 232 194 0 28 0
[pid=12276] ppid=12275 vsize=411064 CPUtime=1.06
/proc/12276/stat : 12276 (java) S 12275 12275 2059 34821 2220 4202496 17725 0 1 0 94 12 0 0 25 0 9 0 875329102 420929536 16993 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 0 0 16800975 18446744073709551615 0 0 17 0 0 0 0
/proc/12276/statm: 102766 16993 2885 10 0 96946 0
[pid=12276/tid=12277] ppid=12275 vsize=411064 CPUtime=0.6
/proc/12276/task/12277/stat : 12277 (java) S 12275 12275 2059 34821 2220 4202560 5145 0 1 0 57 3 0 0 25 0 9 0 875329103 420929536 16993 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 4 0 16800975 18446612132549436544 0 0 -1 0 0 0 0
[pid=12276/tid=12279] ppid=12275 vsize=411064 CPUtime=0.38
/proc/12276/task/12279/stat : 12279 (java) S 12275 12275 2059 34821 2220 4202560 11132 0 0 0 32 6 0 0 20 0 9 0 875329104 420929536 16993 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 0 0 16800975 18446612132549436544 0 0 -1 0 0 0 0
[pid=12276/tid=12280] ppid=12275 vsize=411064 CPUtime=0
/proc/12276/task/12280/stat : 12280 (java) S 12275 12275 2059 34821 2220 4202560 19 0 0 0 0 0 0 0 16 0 9 0 875329104 420929536 16993 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 4 0 16800975 18446612132549436544 0 0 -1 0 0 0 0
[pid=12276/tid=12281] ppid=12275 vsize=411064 CPUtime=0
/proc/12276/task/12281/stat : 12281 (java) S 12275 12275 2059 34821 2220 4202560 5 0 0 0 0 0 0 0 24 0 9 0 875329104 420929536 16993 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 4 0 16800975 18446612132549436544 0 0 -1 0 0 0 0
[pid=12276/tid=12282] ppid=12275 vsize=411064 CPUtime=0
/proc/12276/task/12282/stat : 12282 (java) S 12275 12275 2059 34821 2220 4202560 1 0 0 0 0 0 0 0 25 0 9 0 875329105 420929536 16993 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 4 0 16800975 18446612132549436544 0 0 -1 0 0 0 0
[pid=12276/tid=12283] ppid=12275 vsize=411064 CPUtime=0.07
/proc/12276/task/12283/stat : 12283 (java) S 12275 12275 2059 34821 2220 4202560 508 0 0 0 5 2 0 0 20 0 9 0 875329105 420929536 16993 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 4 0 16800975 18446612132549436544 0 0 -1 0 0 0 0
[pid=12276/tid=12284] ppid=12275 vsize=411064 CPUtime=0
/proc/12276/task/12284/stat : 12284 (java) S 12275 12275 2059 34821 2220 4202560 0 0 0 0 0 0 0 0 25 0 9 0 875329105 420929536 16993 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 4 0 16800975 18446612132549436544 0 0 -1 0 0 0 0
[pid=12276/tid=12285] ppid=12275 vsize=411064 CPUtime=0
/proc/12276/task/12285/stat : 12285 (java) S 12275 12275 2059 34821 2220 4202560 0 0 0 0 0 0 0 0 16 0 9 0 875329105 420929536 16993 1283457024 134512640 134550932 4292341488 18446744073709551615 4294960130 0 4 0 16800975 18446612132549436544 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 1.06
Current children cumulated vsize (KiB) 413632

Child status: 0
Real time (s): 1.11674
CPU time (s): 1.08407
CPU user time (s): 0.948059
CPU system time (s): 0.136008
CPU usage (%): 97.0739
Max. virtual memory (cumulated for all children) (KiB): 413632

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 0.948059
system time used= 0.136008
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 18113
page faults= 1
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 465
involuntary context switches= 453

runsolver used 0 second user time and 0 second system time

The end