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/201108251442/aspuncud-paranoid-1.3/rand149.cudf.s-e-l-s.log.runsolver ./aspuncud-paranoid-1.3 /home/misc2010/data/2011/incremental/s-e-l-s/rand149.cudf /home/misc2010/tmp/201108251442/aspuncud-paranoid-1.3/rand149.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.16 1.02 0.69 5/36 5493
/proc/meminfo: memFree=369576/1048576 swapFree=0/0
[pid=5491] ppid=5490 vsize=2584 CPUtime=0
/proc/5491/stat : 5491 (aspuncud-parano) S 5490 5491 4778 34817 4778 4202496 373 0 0 0 0 0 0 0 18 0 1 0 10048489 2646016 279 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/5491/statm: 646 279 234 194 0 33 0
[pid=5492] ppid=5491 vsize=2584 CPUtime=0
/proc/5492/stat : 5492 (aspuncud-parano) R 5491 5491 4778 34817 4778 4202560 110 0 0 0 0 0 0 0 25 0 1 0 10048489 2646016 132 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/5492/statm: 646 132 86 194 0 33 0
[pid=5493] ppid=5492 vsize=2584 CPUtime=0
/proc/5493/stat : 5493 (aspuncud-parano) R 5492 5491 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10048489 2646016 46 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/5493/statm: 646 46 0 194 0 33 0

[startup+0.183078 s]
/proc/loadavg: 1.16 1.02 0.69 5/36 5493
/proc/meminfo: memFree=369576/1048576 swapFree=0/0
[pid=5491] ppid=5490 vsize=2588 CPUtime=0.01
/proc/5491/stat : 5491 (aspuncud-parano) S 5490 5491 4778 34817 4778 4202496 662 2941 0 0 0 0 0 1 25 0 1 0 10048489 2650112 297 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5491/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.213075 s]
/proc/loadavg: 1.16 1.02 0.69 5/36 5493
/proc/meminfo: memFree=369576/1048576 swapFree=0/0
[pid=5491] ppid=5490 vsize=2588 CPUtime=0.01
/proc/5491/stat : 5491 (aspuncud-parano) S 5490 5491 4778 34817 4778 4202496 662 2941 0 0 0 0 0 1 25 0 1 0 10048489 2650112 297 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5491/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.303095 s]
/proc/loadavg: 1.16 1.02 0.69 5/36 5493
/proc/meminfo: memFree=369576/1048576 swapFree=0/0
[pid=5491] ppid=5490 vsize=2588 CPUtime=0.01
/proc/5491/stat : 5491 (aspuncud-parano) S 5490 5491 4778 34817 4778 4202496 662 2941 0 0 0 0 0 1 25 0 1 0 10048489 2650112 297 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5491/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+0.703243 s]
/proc/loadavg: 1.16 1.02 0.69 5/36 5493
/proc/meminfo: memFree=369576/1048576 swapFree=0/0
[pid=5491] ppid=5490 vsize=2588 CPUtime=0.01
/proc/5491/stat : 5491 (aspuncud-parano) S 5490 5491 4778 34817 4778 4202496 662 2941 0 0 0 0 0 1 25 0 1 0 10048489 2650112 297 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5491/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2588

[startup+1.5034 s]
/proc/loadavg: 1.16 1.02 0.69 2/38 5508
/proc/meminfo: memFree=348840/1048576 swapFree=0/0
[pid=5491] ppid=5490 vsize=2588 CPUtime=0.01
/proc/5491/stat : 5491 (aspuncud-parano) S 5490 5491 4778 34817 4778 4202496 662 2941 0 0 0 0 0 1 25 0 1 0 10048489 2650112 297 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5491/statm: 647 297 251 194 0 34 0
[pid=5506] ppid=5491 vsize=3440 CPUtime=0
/proc/5506/stat : 5506 (unclasp) S 5491 5491 4778 34817 4778 4202496 407 0 0 0 0 0 0 0 25 0 1 0 10048491 3522560 271 1283457024 134512640 135121179 4294148512 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/5506/statm: 860 271 240 149 0 51 0
[pid=5507] ppid=5491 vsize=2696 CPUtime=0
/proc/5507/stat : 5507 (gringo) S 5491 5491 4778 34817 4778 4202496 410 0 0 0 0 0 0 0 25 0 1 0 10048491 2760704 281 1283457024 134512640 137056543 4289209456 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/5507/statm: 674 281 252 622 0 49 0
[pid=5508] ppid=5491 vsize=40452 CPUtime=1.48
/proc/5508/stat : 5508 (cudf2lp) R 5491 5491 4778 34817 4778 4202496 11636 0 0 0 142 6 0 0 25 0 1 0 10048491 41422848 8731 1283457024 134512640 135786343 4288144368 18446744073709551615 134633363 0 0 6 0 0 0 0 17 0 0 0 0
/proc/5508/statm: 10113 8731 126 311 0 9800 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 49176

[startup+3.1038 s]
/proc/loadavg: 1.15 1.02 0.69 3/38 5508
/proc/meminfo: memFree=314988/1048576 swapFree=0/0
[pid=5491] ppid=5490 vsize=2588 CPUtime=2.91
/proc/5491/stat : 5491 (aspuncud-parano) S 5490 5491 4778 34817 4778 4202496 662 26715 0 0 0 0 275 16 16 0 1 0 10048489 2650112 297 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5491/statm: 647 297 251 194 0 34 0
[pid=5506] ppid=5491 vsize=22656 CPUtime=0.16
/proc/5506/stat : 5506 (unclasp) R 5491 5491 4778 34817 4778 4202496 5652 0 0 0 14 2 0 0 18 0 1 0 10048491 23199744 4994 1283457024 134512640 135121179 4294148512 18446744073709551615 134699087 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5506/statm: 5664 4994 289 149 0 4855 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 25244

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

[startup+3.21382 s]
/proc/loadavg: 1.15 1.02 0.69 3/38 5508
/proc/meminfo: memFree=314988/1048576 swapFree=0/0
[pid=5491] ppid=5490 vsize=2588 CPUtime=2.91
/proc/5491/stat : 5491 (aspuncud-parano) S 5490 5491 4778 34817 4778 4202496 662 26715 0 0 0 0 275 16 16 0 1 0 10048489 2650112 297 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5491/statm: 647 297 251 194 0 34 0
[pid=5506] ppid=5491 vsize=27104 CPUtime=0.27
/proc/5506/stat : 5506 (unclasp) R 5491 5491 4778 34817 4778 4202496 7096 0 0 0 25 2 0 0 18 0 1 0 10048491 27754496 6185 1283457024 134512640 135121179 4294148512 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5506/statm: 6776 6185 319 149 0 5967 0
Current children cumulated CPU time (s) 3.18
Current children cumulated vsize (KiB) 29692

[startup+4.00414 s]
/proc/loadavg: 1.15 1.02 0.69 2/36 5508
/proc/meminfo: memFree=344408/1048576 swapFree=0/0
[pid=5491] ppid=5490 vsize=2588 CPUtime=2.91
/proc/5491/stat : 5491 (aspuncud-parano) S 5490 5491 4778 34817 4778 4202496 662 26715 0 0 0 0 275 16 16 0 1 0 10048489 2650112 297 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5491/statm: 647 297 251 194 0 34 0
[pid=5506] ppid=5491 vsize=28792 CPUtime=1.07
/proc/5506/stat : 5506 (unclasp) R 5491 5491 4778 34817 4778 4202496 13184 0 0 0 104 3 0 0 18 0 1 0 10048491 29483008 6301 1283457024 134512640 135121179 4294148512 18446744073709551615 134734434 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5506/statm: 7198 6301 328 149 0 6389 0
Current children cumulated CPU time (s) 3.98
Current children cumulated vsize (KiB) 31380

[startup+4.80445 s]
/proc/loadavg: 1.15 1.02 0.69 2/36 5508
/proc/meminfo: memFree=344292/1048576 swapFree=0/0
[pid=5491] ppid=5490 vsize=2588 CPUtime=2.91
/proc/5491/stat : 5491 (aspuncud-parano) S 5490 5491 4778 34817 4778 4202496 662 26715 0 0 0 0 275 16 16 0 1 0 10048489 2650112 297 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5491/statm: 647 297 251 194 0 34 0
[pid=5506] ppid=5491 vsize=29476 CPUtime=1.86
/proc/5506/stat : 5506 (unclasp) R 5491 5491 4778 34817 4778 4202496 19944 0 0 0 179 7 0 0 20 0 1 0 10048491 30183424 6386 1283457024 134512640 135121179 4294148512 18446744073709551615 134734280 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5506/statm: 7369 6386 328 149 0 6560 0
Current children cumulated CPU time (s) 4.77
Current children cumulated vsize (KiB) 32064

[startup+5.00453 s]
/proc/loadavg: 1.15 1.02 0.69 2/36 5508
/proc/meminfo: memFree=344292/1048576 swapFree=0/0
[pid=5491] ppid=5490 vsize=2588 CPUtime=2.91
/proc/5491/stat : 5491 (aspuncud-parano) S 5490 5491 4778 34817 4778 4202496 662 26715 0 0 0 0 275 16 16 0 1 0 10048489 2650112 297 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5491/statm: 647 297 251 194 0 34 0
[pid=5506] ppid=5491 vsize=28792 CPUtime=2.06
/proc/5506/stat : 5506 (unclasp) R 5491 5491 4778 34817 4778 4202496 21839 0 0 0 198 8 0 0 20 0 1 0 10048491 29483008 6301 1283457024 134512640 135121179 4294148512 18446744073709551615 134734422 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5506/statm: 7198 6301 328 149 0 6389 0
Current children cumulated CPU time (s) 4.97
Current children cumulated vsize (KiB) 31380

[startup+5.10458 s]
/proc/loadavg: 1.15 1.02 0.69 2/36 5508
/proc/meminfo: memFree=344292/1048576 swapFree=0/0
[pid=5491] ppid=5490 vsize=2588 CPUtime=2.91
/proc/5491/stat : 5491 (aspuncud-parano) S 5490 5491 4778 34817 4778 4202496 662 26715 0 0 0 0 275 16 16 0 1 0 10048489 2650112 297 1283457024 134512640 135304128 4293404832 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5491/statm: 647 297 251 194 0 34 0
[pid=5506] ppid=5491 vsize=29376 CPUtime=2.16
/proc/5506/stat : 5506 (unclasp) R 5491 5491 4778 34817 4778 4202496 22906 0 0 0 206 10 0 0 21 0 1 0 10048491 30081024 6447 1283457024 134512640 135121179 4294148512 18446744073709551615 134981267 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5506/statm: 7344 6447 328 149 0 6535 0
Current children cumulated CPU time (s) 5.07
Current children cumulated vsize (KiB) 31964

Child status: 0
Real time (s): 5.1992
CPU time (s): 5.18432
CPU user time (s): 4.89631
CPU system time (s): 0.288018
CPU usage (%): 99.7138
Max. virtual memory (cumulated for all children) (KiB): 77188

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.89631
system time used= 0.288018
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 53398
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= 1273
involuntary context switches= 935

runsolver used 0.008 second user time and 0 second system time

The end