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/201103031013/aspcud-paranoid-1.4/3889.cudf.caixa.log.runsolver ./aspcud-paranoid-1.4 /home/misc2010/data/misc4/caixa//3889.cudf /home/misc2010/tmp/201103031013/aspcud-paranoid-1.4/3889.cudf.caixa.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.80 1.68 1.57 6/38 9774
/proc/meminfo: memFree=294668/1048576 swapFree=0/0
[pid=9758] ppid=9757 vsize=2596 CPUtime=0.01
/proc/9758/stat : 9758 (aspcud-paranoid) R 9757 9758 29493 34817 29493 4202496 630 2942 0 0 0 0 1 0 25 0 1 0 75967891 2658304 298 1283457024 134512640 135304128 4288107424 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0
/proc/9758/statm: 649 298 250 194 0 36 0
[pid=9772] ppid=9758 vsize=2596 CPUtime=0
/proc/9772/stat : 9772 (aspcud-paranoid) R 9758 9758 29493 34817 29493 4202560 111 0 0 0 0 0 0 0 25 0 1 0 75967893 2658304 132 1283457024 134512640 135304128 4288107424 18446744073709551615 4294960130 0 0 6 1132494585 0 0 0 17 0 0 0 0
/proc/9772/statm: 649 132 83 194 0 36 0
[pid=9773] ppid=9758 vsize=2596 CPUtime=0
/proc/9773/stat : 9773 (aspcud-paranoid) S 9758 9758 29493 34817 29493 4202560 110 0 0 0 0 0 0 0 25 0 1 0 75967893 2658304 132 1283457024 134512640 135304128 4288107424 18446744073709551615 4294960130 0 0 6 1132494585 18446744071564457842 0 0 17 0 0 0 0
/proc/9773/statm: 649 132 83 194 0 36 0
[pid=9774] ppid=9758 vsize=2596 CPUtime=0
/proc/9774/stat : 9774 (aspcud-paranoid) R 9758 9758 29493 34817 29493 4202560 0 0 0 0 0 0 0 0 25 0 1 0 75967893 2658304 48 1283457024 134512640 135304128 4288107424 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0
/proc/9774/statm: 649 48 0 194 0 36 0

[startup+0.193862 s]
/proc/loadavg: 1.80 1.68 1.57 6/38 9774
/proc/meminfo: memFree=294668/1048576 swapFree=0/0
[pid=9758] ppid=9757 vsize=2596 CPUtime=0.01
/proc/9758/stat : 9758 (aspcud-paranoid) S 9757 9758 29493 34817 29493 4202496 656 2942 0 0 0 0 1 0 25 0 1 0 75967891 2658304 299 1283457024 134512640 135304128 4288107424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9758/statm: 649 299 251 194 0 36 0
[pid=9772] ppid=9758 vsize=1888 CPUtime=0
/proc/9772/stat : 9772 (clasp) S 9758 9758 29493 34817 29493 4202496 289 0 0 0 0 0 0 0 25 0 1 0 75967893 1933312 156 1283457024 134512640 136241547 4291909360 18446744073709551615 135683070 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/9772/statm: 472 156 140 423 0 47 0
[pid=9773] ppid=9758 vsize=2612 CPUtime=0
/proc/9773/stat : 9773 (gringo) S 9758 9758 29493 34817 29493 4202496 409 0 0 0 0 0 0 0 25 0 1 0 75967893 2674688 277 1283457024 134512640 136959103 4287017664 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9773/statm: 653 277 247 598 0 52 0
[pid=9774] ppid=9758 vsize=12444 CPUtime=0.17
/proc/9774/stat : 9774 (cudf2lp) R 9758 9758 29493 34817 29493 4202496 3117 0 0 0 16 1 0 0 25 0 1 0 75967893 12742656 2758 1283457024 134512640 135749763 4288683120 18446744073709551615 134561899 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9774/statm: 3111 2758 119 303 0 2806 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 19540

[startup+0.203877 s]
/proc/loadavg: 1.80 1.68 1.57 6/38 9774
/proc/meminfo: memFree=294668/1048576 swapFree=0/0
[pid=9758] ppid=9757 vsize=2596 CPUtime=0.01
/proc/9758/stat : 9758 (aspcud-paranoid) S 9757 9758 29493 34817 29493 4202496 656 2942 0 0 0 0 1 0 25 0 1 0 75967891 2658304 299 1283457024 134512640 135304128 4288107424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9758/statm: 649 299 251 194 0 36 0
[pid=9772] ppid=9758 vsize=1888 CPUtime=0
/proc/9772/stat : 9772 (clasp) S 9758 9758 29493 34817 29493 4202496 289 0 0 0 0 0 0 0 25 0 1 0 75967893 1933312 156 1283457024 134512640 136241547 4291909360 18446744073709551615 135683070 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/9772/statm: 472 156 140 423 0 47 0
[pid=9773] ppid=9758 vsize=2612 CPUtime=0
/proc/9773/stat : 9773 (gringo) S 9758 9758 29493 34817 29493 4202496 409 0 0 0 0 0 0 0 25 0 1 0 75967893 2674688 277 1283457024 134512640 136959103 4287017664 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9773/statm: 653 277 247 598 0 52 0
[pid=9774] ppid=9758 vsize=12444 CPUtime=0.19
/proc/9774/stat : 9774 (cudf2lp) R 9758 9758 29493 34817 29493 4202496 3123 0 0 0 18 1 0 0 25 0 1 0 75967893 12742656 2764 1283457024 134512640 135749763 4288683120 18446744073709551615 134562294 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9774/statm: 3111 2764 119 303 0 2806 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 19540

[startup+0.313891 s]
/proc/loadavg: 1.80 1.68 1.57 6/38 9774
/proc/meminfo: memFree=294668/1048576 swapFree=0/0
[pid=9758] ppid=9757 vsize=2596 CPUtime=0.01
/proc/9758/stat : 9758 (aspcud-paranoid) S 9757 9758 29493 34817 29493 4202496 656 2942 0 0 0 0 1 0 25 0 1 0 75967891 2658304 299 1283457024 134512640 135304128 4288107424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9758/statm: 649 299 251 194 0 36 0
[pid=9772] ppid=9758 vsize=1888 CPUtime=0
/proc/9772/stat : 9772 (clasp) S 9758 9758 29493 34817 29493 4202496 289 0 0 0 0 0 0 0 25 0 1 0 75967893 1933312 156 1283457024 134512640 136241547 4291909360 18446744073709551615 135683070 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/9772/statm: 472 156 140 423 0 47 0
[pid=9773] ppid=9758 vsize=2612 CPUtime=0
/proc/9773/stat : 9773 (gringo) S 9758 9758 29493 34817 29493 4202496 409 0 0 0 0 0 0 0 25 0 1 0 75967893 2674688 277 1283457024 134512640 136959103 4287017664 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9773/statm: 653 277 247 598 0 52 0
[pid=9774] ppid=9758 vsize=14788 CPUtime=0.29
/proc/9774/stat : 9774 (cudf2lp) R 9758 9758 29493 34817 29493 4202496 3775 0 0 0 27 2 0 0 25 0 1 0 75967893 15142912 3367 1283457024 134512640 135749763 4288683120 18446744073709551615 135199161 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9774/statm: 3697 3367 119 303 0 3392 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 21884

[startup+0.714295 s]
/proc/loadavg: 1.80 1.68 1.57 6/38 9774
/proc/meminfo: memFree=294668/1048576 swapFree=0/0
[pid=9758] ppid=9757 vsize=2596 CPUtime=0.01
/proc/9758/stat : 9758 (aspcud-paranoid) S 9757 9758 29493 34817 29493 4202496 656 2942 0 0 0 0 1 0 25 0 1 0 75967891 2658304 299 1283457024 134512640 135304128 4288107424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9758/statm: 649 299 251 194 0 36 0
[pid=9772] ppid=9758 vsize=2696 CPUtime=0
/proc/9772/stat : 9772 (clasp) R 9758 9758 29493 34817 29493 4202496 527 0 0 0 0 0 0 0 19 0 1 0 75967893 2760704 394 1283457024 134512640 136241547 4291909360 18446744073709551615 135683070 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9772/statm: 674 394 174 423 0 249 0
[pid=9773] ppid=9758 vsize=3784 CPUtime=0.06
/proc/9773/stat : 9773 (gringo) S 9758 9758 29493 34817 29493 4202496 717 0 0 0 6 0 0 0 19 0 1 0 75967893 3874816 552 1283457024 134512640 136959103 4287017664 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9773/statm: 946 552 247 598 0 345 0
[pid=9774] ppid=9758 vsize=36596 CPUtime=0.62
/proc/9774/stat : 9774 (cudf2lp) R 9758 9758 29493 34817 29493 4202496 10000 0 0 0 57 5 0 0 25 0 1 0 75967893 37474304 8913 1283457024 134512640 135749763 4288683120 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9774/statm: 9149 8913 128 303 0 8844 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 45672

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

[startup+0.804004 s]
/proc/loadavg: 1.80 1.68 1.57 6/38 9774
/proc/meminfo: memFree=294668/1048576 swapFree=0/0
[pid=9758] ppid=9757 vsize=2596 CPUtime=0.01
/proc/9758/stat : 9758 (aspcud-paranoid) S 9757 9758 29493 34817 29493 4202496 656 2942 0 0 0 0 1 0 25 0 1 0 75967891 2658304 299 1283457024 134512640 135304128 4288107424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9758/statm: 649 299 251 194 0 36 0
[pid=9772] ppid=9758 vsize=3720 CPUtime=0
/proc/9772/stat : 9772 (clasp) S 9758 9758 29493 34817 29493 4202496 774 0 0 0 0 0 0 0 18 0 1 0 75967893 3809280 641 1283457024 134512640 136241547 4291909360 18446744073709551615 135683070 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/9772/statm: 930 641 175 423 0 505 0
[pid=9773] ppid=9758 vsize=5288 CPUtime=0.16
/proc/9773/stat : 9773 (gringo) R 9758 9758 29493 34817 29493 4202496 1152 0 0 0 16 0 0 0 19 0 1 0 75967893 5414912 873 1283457024 134512640 136959103 4287017664 18446744073709551615 134697235 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9773/statm: 1322 873 247 598 0 721 0
[pid=9774] ppid=9758 vsize=36596 CPUtime=0.62
/proc/9774/stat : 9774 (cudf2lp) R 9758 9758 29493 34817 29493 4202496 10000 0 0 0 57 5 0 0 25 0 1 0 75967893 37474304 8913 1283457024 134512640 135749763 4288683120 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9774/statm: 9149 8913 128 303 0 8844 0
Current children cumulated CPU time (s) 0.79
Current children cumulated vsize (KiB) 48200

[startup+1.20412 s]
/proc/loadavg: 1.80 1.68 1.57 3/38 9775
/proc/meminfo: memFree=281196/1048576 swapFree=0/0
[pid=9758] ppid=9757 vsize=2596 CPUtime=0.77
/proc/9758/stat : 9758 (aspcud-paranoid) S 9757 9758 29493 34817 29493 4202496 656 12946 0 0 0 0 70 7 18 0 1 0 75967891 2658304 299 1283457024 134512640 135304128 4288107424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9758/statm: 649 299 251 194 0 36 0
[pid=9772] ppid=9758 vsize=10792 CPUtime=0.02
/proc/9772/stat : 9772 (clasp) R 9758 9758 29493 34817 29493 4202496 2858 0 0 0 2 0 0 0 18 0 1 0 75967893 11051008 2339 1283457024 134512640 136241547 4291909360 18446744073709551615 135683070 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9772/statm: 2698 2339 175 423 0 2273 0
[pid=9773] ppid=9758 vsize=16300 CPUtime=0.4
/proc/9773/stat : 9773 (gringo) R 9758 9758 29493 34817 29493 4202496 3934 0 0 0 38 2 0 0 18 0 1 0 75967893 16691200 3172 1283457024 134512640 136959103 4287017664 18446744073709551615 134919380 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9773/statm: 4075 3172 256 598 0 3474 0
Current children cumulated CPU time (s) 1.19
Current children cumulated vsize (KiB) 29688

[startup+1.40418 s]
/proc/loadavg: 1.80 1.68 1.57 3/38 9775
/proc/meminfo: memFree=281196/1048576 swapFree=0/0
[pid=9758] ppid=9757 vsize=2596 CPUtime=0.77
/proc/9758/stat : 9758 (aspcud-paranoid) S 9757 9758 29493 34817 29493 4202496 656 12946 0 0 0 0 70 7 18 0 1 0 75967891 2658304 299 1283457024 134512640 135304128 4288107424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9758/statm: 649 299 251 194 0 36 0
[pid=9772] ppid=9758 vsize=14248 CPUtime=0.07
/proc/9772/stat : 9772 (clasp) R 9758 9758 29493 34817 29493 4202496 3747 0 0 0 7 0 0 0 18 0 1 0 75967893 14589952 3228 1283457024 134512640 136241547 4291909360 18446744073709551615 135683070 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/9772/statm: 3562 3228 177 423 0 3137 0
[pid=9773] ppid=9758 vsize=19400 CPUtime=0.55
/proc/9773/stat : 9773 (gringo) R 9758 9758 29493 34817 29493 4202496 5096 0 0 0 53 2 0 0 18 0 1 0 75967893 19865600 3986 1283457024 134512640 136959103 4287017664 18446744073709551615 136198489 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9773/statm: 4850 3986 259 598 0 4249 0
Current children cumulated CPU time (s) 1.39
Current children cumulated vsize (KiB) 36244

Child status: 0
Real time (s): 1.49897
CPU time (s): 1.50009
CPU user time (s): 1.34008
CPU system time (s): 0.16001
CPU usage (%): 100.075
Max. virtual memory (cumulated for all children) (KiB): 51116

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 1.34008
system time used= 0.16001
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 35778
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= 639
involuntary context switches= 562

runsolver used 0 second user time and 0 second system time

The end