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/201108241238/aspuncud-trendy-1.3/rand576.cudf.s-e-l-s.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l-s/rand576.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand576.cudf.s-e-l-s.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.06 1.03 1.00 5/37 18999
/proc/meminfo: memFree=565844/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2584 CPUtime=0.01
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 372 0 0 0 0 1 0 0 18 0 1 0 4266672 2646016 279 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/18997/statm: 646 279 234 194 0 33 0
[pid=18998] ppid=18997 vsize=2584 CPUtime=0
/proc/18998/stat : 18998 (aspuncud-trendy) R 18997 18997 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 4266672 2646016 132 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/18998/statm: 646 132 86 194 0 33 0
[pid=18999] ppid=18998 vsize=2584 CPUtime=0
/proc/18999/stat : 18999 (aspuncud-trendy) R 18998 18997 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4266672 2646016 46 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/18999/statm: 646 46 0 194 0 33 0

[startup+0.193802 s]
/proc/loadavg: 1.06 1.03 1.00 5/37 18999
/proc/meminfo: memFree=565844/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=0.01
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 617 2231 0 0 0 1 0 0 25 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.21184 s]
/proc/loadavg: 1.06 1.03 1.00 5/37 18999
/proc/meminfo: memFree=565844/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=0.01
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 617 2231 0 0 0 1 0 0 25 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.305799 s]
/proc/loadavg: 1.06 1.03 1.00 5/37 18999
/proc/meminfo: memFree=565844/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=0.01
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 617 2231 0 0 0 1 0 0 25 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.712233 s]
/proc/loadavg: 1.06 1.03 1.00 5/37 18999
/proc/meminfo: memFree=565844/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=0.01
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 617 2231 0 0 0 1 0 0 25 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+1.50588 s]
/proc/loadavg: 1.06 1.03 1.00 2/39 19011
/proc/meminfo: memFree=529640/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=0.01
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 617 2231 0 0 0 1 0 0 25 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
[pid=19009] ppid=18997 vsize=3444 CPUtime=0
/proc/19009/stat : 19009 (unclasp) S 18997 18997 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 4266674 3526656 272 1283457024 134512640 135121179 4294746672 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/19009/statm: 861 272 240 149 0 52 0
[pid=19010] ppid=18997 vsize=2696 CPUtime=0
/proc/19010/stat : 19010 (gringo) S 18997 18997 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 4266674 2760704 281 1283457024 134512640 137056543 4287328944 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/19010/statm: 674 281 252 622 0 49 0
[pid=19011] ppid=18997 vsize=40444 CPUtime=1.37
/proc/19011/stat : 19011 (cudf2lp) R 18997 18997 1511 34817 1511 4202496 11610 0 0 0 131 6 0 0 25 0 1 0 4266674 41414656 8706 1283457024 134512640 135786343 4288769168 18446744073709551615 135199569 0 0 6 0 0 0 0 17 0 0 0 0
/proc/19011/statm: 10111 8706 126 311 0 9798 0
Current children cumulated CPU time (s) 1.38
Current children cumulated vsize (KiB) 49172

[startup+3.10297 s]
/proc/loadavg: 1.06 1.03 1.00 3/39 19011
/proc/meminfo: memFree=490680/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=2.05
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 617 17921 0 0 0 1 195 9 18 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
[pid=19009] ppid=18997 vsize=21724 CPUtime=0.09
/proc/19009/stat : 19009 (unclasp) R 18997 18997 1511 34817 1511 4202496 5610 0 0 0 8 1 0 0 18 0 1 0 4266674 22245376 4817 1283457024 134512640 135121179 4294746672 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/19009/statm: 5431 4817 277 149 0 4622 0
[pid=19010] ppid=18997 vsize=26248 CPUtime=0.84
/proc/19010/stat : 19010 (gringo) R 18997 18997 1511 34817 1511 4202496 7716 0 0 0 82 2 0 0 18 0 1 0 4266674 26877952 5450 1283457024 134512640 137056543 4287328944 18446744073709551615 134757936 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/19010/statm: 6562 5450 268 622 0 5937 0
Current children cumulated CPU time (s) 2.98
Current children cumulated vsize (KiB) 50560

[startup+6.30379 s]
/proc/loadavg: 1.06 1.03 1.00 2/37 19011
/proc/meminfo: memFree=505104/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=3.36
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 617 31114 0 0 0 1 320 15 15 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
[pid=19009] ppid=18997 vsize=45508 CPUtime=2.83
/proc/19009/stat : 19009 (unclasp) R 18997 18997 1511 34817 1511 4202496 32940 0 0 0 267 16 0 0 22 0 1 0 4266674 46600192 10219 1283457024 134512640 135121179 4294746672 18446744073709551615 134980996 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/19009/statm: 11377 10219 328 149 0 10568 0
Current children cumulated CPU time (s) 6.19
Current children cumulated vsize (KiB) 48096

[startup+12.7062 s]
/proc/loadavg: 1.05 1.03 1.00 2/36 19011
/proc/meminfo: memFree=506112/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=3.36
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 617 31114 0 0 0 1 320 15 15 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
[pid=19009] ppid=18997 vsize=44596 CPUtime=9.22
/proc/19009/stat : 19009 (unclasp) R 18997 18997 1511 34817 1511 4202496 112626 0 0 0 871 51 0 0 25 0 1 0 4266674 45666304 9992 1283457024 134512640 135121179 4294746672 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/19009/statm: 11149 9992 328 149 0 10340 0
Current children cumulated CPU time (s) 12.58
Current children cumulated vsize (KiB) 47184

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

[startup+12.8062 s]
/proc/loadavg: 1.05 1.03 1.00 2/36 19011
/proc/meminfo: memFree=506112/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=3.36
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 617 31114 0 0 0 1 320 15 15 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
[pid=19009] ppid=18997 vsize=45508 CPUtime=9.32
/proc/19009/stat : 19009 (unclasp) R 18997 18997 1511 34817 1511 4202496 113868 0 0 0 881 51 0 0 25 0 1 0 4266674 46600192 10220 1283457024 134512640 135121179 4294746672 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/19009/statm: 11377 10220 328 149 0 10568 0
Current children cumulated CPU time (s) 12.68
Current children cumulated vsize (KiB) 48096

[startup+19.2086 s]
/proc/loadavg: 1.04 1.03 1.00 2/36 19011
/proc/meminfo: memFree=505492/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=3.36
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 617 31114 0 0 0 1 320 15 15 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
[pid=19009] ppid=18997 vsize=44872 CPUtime=15.72
/proc/19009/stat : 19009 (unclasp) R 18997 18997 1511 34817 1511 4202496 177927 0 0 0 1493 79 0 0 25 0 1 0 4266674 45948928 10058 1283457024 134512640 135121179 4294746672 18446744073709551615 134643694 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/19009/statm: 11218 10058 333 149 0 10409 0
Current children cumulated CPU time (s) 19.08
Current children cumulated vsize (KiB) 47460

[startup+22.41 s]
/proc/loadavg: 1.04 1.03 1.00 2/36 19011
/proc/meminfo: memFree=505368/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=3.36
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 617 31114 0 0 0 1 320 15 15 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
[pid=19009] ppid=18997 vsize=44872 CPUtime=18.92
/proc/19009/stat : 19009 (unclasp) R 18997 18997 1511 34817 1511 4202496 216965 0 0 0 1798 94 0 0 25 0 1 0 4266674 45948928 10058 1283457024 134512640 135121179 4294746672 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/19009/statm: 11218 10058 333 149 0 10409 0
Current children cumulated CPU time (s) 22.28
Current children cumulated vsize (KiB) 47460

[startup+23.2104 s]
/proc/loadavg: 1.04 1.03 1.00 2/36 19011
/proc/meminfo: memFree=505120/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=3.36
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 617 31114 0 0 0 1 320 15 15 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
[pid=19009] ppid=18997 vsize=45032 CPUtime=19.71
/proc/19009/stat : 19009 (unclasp) R 18997 18997 1511 34817 1511 4202496 226497 0 0 0 1870 101 0 0 25 0 1 0 4266674 46112768 10098 1283457024 134512640 135121179 4294746672 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/19009/statm: 11258 10098 333 149 0 10449 0
Current children cumulated CPU time (s) 23.07
Current children cumulated vsize (KiB) 47620

[startup+23.6106 s]
/proc/loadavg: 1.04 1.03 1.00 2/36 19011
/proc/meminfo: memFree=505120/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=3.36
/proc/18997/stat : 18997 (aspuncud-trendy) S 18996 18997 1511 34817 1511 4202496 617 31114 0 0 0 1 320 15 15 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
[pid=19009] ppid=18997 vsize=45032 CPUtime=20.11
/proc/19009/stat : 19009 (unclasp) R 18997 18997 1511 34817 1511 4202496 231252 0 0 0 1907 104 0 0 25 0 1 0 4266674 46112768 10107 1283457024 134512640 135121179 4294746672 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/19009/statm: 11258 10107 333 149 0 10449 0
Current children cumulated CPU time (s) 23.47
Current children cumulated vsize (KiB) 47620

[startup+23.8107 s]
/proc/loadavg: 1.04 1.03 1.00 2/36 19011
/proc/meminfo: memFree=505120/1048576 swapFree=0/0
[pid=18997] ppid=18996 vsize=2588 CPUtime=23.68
/proc/18997/stat : 18997 (aspuncud-trendy) R 18996 18997 1511 34817 1511 4202496 727 265633 0 0 0 2 2244 122 20 0 1 0 4266672 2650112 297 1283457024 134512640 135304128 4290706960 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/18997/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 23.68
Current children cumulated vsize (KiB) 2588

Child status: 0
Real time (s): 23.8154
CPU time (s): 23.6935
CPU user time (s): 22.4494
CPU system time (s): 1.24408
CPU usage (%): 99.4881
Max. virtual memory (cumulated for all children) (KiB): 88084

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 22.4494
system time used= 1.24408
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 267387
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2020
involuntary context switches= 1752

runsolver used 0 second user time and 0 second system time

The end