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: runsolver -s SIGUSR1 -M 1124 -C 300 -d 10 -w /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/upgrade/difficult/rand981.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand981.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/upgrade/difficult/rand981.cudf.result -notuptodate(solution),-aligned(solution,source,sourceversion),-unsat_recommends(solution),-count(new) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 300 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 330 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.22 1.12 1.08 2/64 12611
/proc/meminfo: memFree=510100/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=1068 CPUtime=0
/proc/12611/stat : 12611 (aspcud-full) D 12610 12611 1745 0 -1 4194304 75 0 0 0 0 0 0 0 20 0 1 0 117972340 1093632 1 18446744073709551615 0 0 140736421178283 4288208288 4151960624 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/12611/statm: 267 1 0 0 0 28 0

[startup+0.169278 s]
/proc/loadavg: 1.22 1.12 1.08 2/64 12611
/proc/meminfo: memFree=510100/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=9212 CPUtime=0.06
/proc/12611/stat : 12611 (aspcud-full) S 12610 12611 1745 0 -1 4202496 730 3615 2 7 0 1 4 1 20 0 1 0 117972340 9433088 364 18446744073709551615 4194304 5129932 140736421175648 140736421174304 139909677208670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/12611/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.200324 s]
/proc/loadavg: 1.22 1.12 1.08 2/64 12611
/proc/meminfo: memFree=510100/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=9212 CPUtime=0.06
/proc/12611/stat : 12611 (aspcud-full) S 12610 12611 1745 0 -1 4202496 730 3615 2 7 0 1 4 1 20 0 1 0 117972340 9433088 364 18446744073709551615 4194304 5129932 140736421175648 140736421174304 139909677208670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/12611/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.300317 s]
/proc/loadavg: 1.22 1.12 1.08 2/64 12611
/proc/meminfo: memFree=510100/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=9212 CPUtime=0.06
/proc/12611/stat : 12611 (aspcud-full) S 12610 12611 1745 0 -1 4202496 730 3615 2 7 0 1 4 1 20 0 1 0 117972340 9433088 364 18446744073709551615 4194304 5129932 140736421175648 140736421174304 139909677208670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/12611/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+0.700228 s]
/proc/loadavg: 1.22 1.12 1.08 2/64 12611
/proc/meminfo: memFree=510100/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=9212 CPUtime=0.06
/proc/12611/stat : 12611 (aspcud-full) S 12610 12611 1745 0 -1 4202496 730 3615 2 7 0 1 4 1 20 0 1 0 117972340 9433088 364 18446744073709551615 4194304 5129932 140736421175648 140736421174304 139909677208670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/12611/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 1.22 1.12 1.08 2/66 12627
/proc/meminfo: memFree=475364/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=9212 CPUtime=0.06
/proc/12611/stat : 12611 (aspcud-full) S 12610 12611 1745 0 -1 4202496 730 3615 2 7 0 1 4 1 20 0 1 0 117972340 9433088 364 18446744073709551615 4194304 5129932 140736421175648 140736421174304 139909677208670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/12611/statm: 2303 364 303 229 0 63 0
[pid=12627] ppid=12611 vsize=31648 CPUtime=1.34
/proc/12627/stat : 12627 (cudf2lp) R 12611 12611 1745 0 -1 4202496 9299 0 1 0 130 4 0 0 20 0 1 0 117972351 32407552 7567 18446744073709551615 4194304 5690517 140736291447760 140736291445416 4293615 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/12627/statm: 7912 7567 160 366 0 7543 0
Current children cumulated CPU time (s) 1.4
Current children cumulated vsize (KiB) 40860

[startup+3.10032 s]
/proc/loadavg: 1.22 1.12 1.08 2/66 12627
/proc/meminfo: memFree=442008/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=9212 CPUtime=0.06
/proc/12611/stat : 12611 (aspcud-full) S 12610 12611 1745 0 -1 4202496 730 3615 2 7 0 1 4 1 20 0 1 0 117972340 9433088 364 18446744073709551615 4194304 5129932 140736421175648 140736421174304 139909677208670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/12611/statm: 2303 364 303 229 0 63 0
[pid=12627] ppid=12611 vsize=112460 CPUtime=2.93
/proc/12627/stat : 12627 (cudf2lp) R 12611 12611 1745 0 -1 4202496 27929 0 1 0 281 12 0 0 20 0 1 0 117972351 115159040 24532 18446744073709551615 4194304 5690517 140736291447760 140736291443928 4956989 0 0 16781316 0 0 0 0 17 0 0 0 3 0 0
/proc/12627/statm: 28115 24532 160 366 0 27746 0
Current children cumulated CPU time (s) 2.99
Current children cumulated vsize (KiB) 121672

[startup+6.3003 s]
/proc/loadavg: 1.21 1.12 1.08 2/66 12628
/proc/meminfo: memFree=458128/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=9212 CPUtime=5.34
/proc/12611/stat : 12611 (aspcud-full) S 12610 12611 1745 0 -1 4202496 754 44890 2 8 0 1 504 29 20 0 1 0 117972340 9433088 364 18446744073709551615 4194304 5129932 140736421175648 140736421174304 139909677208670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/12611/statm: 2303 364 303 229 0 63 0
[pid=12628] ppid=12611 vsize=24556 CPUtime=0.82
/proc/12628/stat : 12628 (gringo) R 12611 12611 1745 0 -1 4202496 6822 0 0 0 77 5 0 0 20 0 1 0 117972887 25145344 5227 18446744073709551615 4194304 6531320 140733453597536 140733453594152 4359010 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/12628/statm: 6139 5227 259 571 0 5560 0
Current children cumulated CPU time (s) 6.16
Current children cumulated vsize (KiB) 33768

[startup+12.7003 s]
/proc/loadavg: 1.19 1.11 1.08 2/66 12628
/proc/meminfo: memFree=38636/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=9212 CPUtime=5.34
/proc/12611/stat : 12611 (aspcud-full) S 12610 12611 1745 0 -1 4202496 754 44890 2 8 0 1 504 29 20 0 1 0 117972340 9433088 364 18446744073709551615 4194304 5129932 140736421175648 140736421174304 139909677208670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/12611/statm: 2303 364 303 229 0 63 0
[pid=12628] ppid=12611 vsize=569300 CPUtime=7.1
/proc/12628/stat : 12628 (gringo) R 12611 12611 1745 0 -1 4202496 133736 0 0 0 661 49 0 0 20 0 1 0 117972887 582963200 115239 18446744073709551615 4194304 6531320 140733453597536 140733453593880 4605483 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/12628/statm: 142325 115239 282 571 0 141746 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 578512

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

[startup+12.8003 s]
/proc/loadavg: 1.19 1.11 1.08 2/66 12628
/proc/meminfo: memFree=38636/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=9212 CPUtime=5.34
/proc/12611/stat : 12611 (aspcud-full) S 12610 12611 1745 0 -1 4202496 754 44890 2 8 0 1 504 29 20 0 1 0 117972340 9433088 364 18446744073709551615 4194304 5129932 140736421175648 140736421174304 139909677208670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/12611/statm: 2303 364 303 229 0 63 0
[pid=12628] ppid=12611 vsize=577512 CPUtime=7.19
/proc/12628/stat : 12628 (gringo) R 12611 12611 1745 0 -1 4202496 135604 0 0 0 669 50 0 0 20 0 1 0 117972887 591372288 117107 18446744073709551615 4194304 6531320 140733453597536 140733453593976 5563228 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/12628/statm: 144378 117107 282 571 0 143799 0
Current children cumulated CPU time (s) 12.53
Current children cumulated vsize (KiB) 586724

[startup+14.4035 s]
/proc/loadavg: 1.19 1.11 1.08 2/67 12630
/proc/meminfo: memFree=318088/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=9212 CPUtime=13.19
/proc/12611/stat : 12611 (aspcud-full) S 12610 12611 1745 0 -1 4202496 791 180791 2 8 0 1 1227 91 20 0 1 0 117972340 9433088 364 18446744073709551615 4194304 5129932 140736421175648 140736421173712 139909677208670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/12611/statm: 2303 364 303 229 0 63 0
[pid=12629] ppid=12611 vsize=174836 CPUtime=0.91
/proc/12629/stat : 12629 (clasp) R 12611 12611 1745 0 -1 4202496 48231 0 0 0 79 12 0 0 20 0 1 0 117973687 179032064 41995 18446744073709551615 4194304 6238623 140733450831904 140733450829384 5442611 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/12629/statm: 43709 41995 241 500 0 43206 0
[pid=12630] ppid=12611 vsize=22040 CPUtime=0
/proc/12630/stat : 12630 (parse.py) S 12611 12611 1745 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 117973687 22568960 1129 18446744073709551615 4194304 6642060 140734287703696 140734287702056 140346467407648 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/12630/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 14.1
Current children cumulated vsize (KiB) 206088

[startup+15.2003 s]
/proc/loadavg: 1.19 1.11 1.08 2/67 12630
/proc/meminfo: memFree=318088/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=9212 CPUtime=13.19
/proc/12611/stat : 12611 (aspcud-full) S 12610 12611 1745 0 -1 4202496 791 180791 2 8 0 1 1227 91 20 0 1 0 117972340 9433088 364 18446744073709551615 4194304 5129932 140736421175648 140736421173712 139909677208670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/12611/statm: 2303 364 303 229 0 63 0
[pid=12629] ppid=12611 vsize=162532 CPUtime=1.71
/proc/12629/stat : 12629 (clasp) R 12611 12611 1745 0 -1 4202496 48292 0 0 0 158 13 0 0 20 0 1 0 117973687 166432768 39777 18446744073709551615 4194304 6238623 140733450831904 140733450829600 4356208 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/12629/statm: 40633 39777 263 500 0 40130 0
[pid=12630] ppid=12611 vsize=22040 CPUtime=0
/proc/12630/stat : 12630 (parse.py) S 12611 12611 1745 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 117973687 22568960 1129 18446744073709551615 4194304 6642060 140734287703696 140734287702056 140346467407648 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/12630/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 14.9
Current children cumulated vsize (KiB) 193784

[startup+16.0003 s]
/proc/loadavg: 1.17 1.11 1.08 2/67 12630
/proc/meminfo: memFree=318088/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=9212 CPUtime=13.19
/proc/12611/stat : 12611 (aspcud-full) S 12610 12611 1745 0 -1 4202496 791 180791 2 8 0 1 1227 91 20 0 1 0 117972340 9433088 364 18446744073709551615 4194304 5129932 140736421175648 140736421173712 139909677208670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/12611/statm: 2303 364 303 229 0 63 0
[pid=12629] ppid=12611 vsize=162532 CPUtime=2.5
/proc/12629/stat : 12629 (clasp) R 12611 12611 1745 0 -1 4202496 48293 0 0 0 237 13 0 0 20 0 1 0 117973687 166432768 39778 18446744073709551615 4194304 6238623 140733450831904 140733450828928 4356208 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/12629/statm: 40633 39778 264 500 0 40130 0
[pid=12630] ppid=12611 vsize=22040 CPUtime=0
/proc/12630/stat : 12630 (parse.py) S 12611 12611 1745 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 117973687 22568960 1129 18446744073709551615 4194304 6642060 140734287703696 140734287702056 140346467407648 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/12630/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 15.69
Current children cumulated vsize (KiB) 193784

[startup+16.2003 s]
/proc/loadavg: 1.17 1.11 1.08 2/67 12630
/proc/meminfo: memFree=318088/1022884 swapFree=0/0
[pid=12611] ppid=12610 vsize=9212 CPUtime=13.19
/proc/12611/stat : 12611 (aspcud-full) S 12610 12611 1745 0 -1 4202496 791 180791 2 8 0 1 1227 91 20 0 1 0 117972340 9433088 364 18446744073709551615 4194304 5129932 140736421175648 140736421173712 139909677208670 0 65536 16781316 1115778811 0 0 0 17 0 0 0 1 0 0
/proc/12611/statm: 2303 364 303 229 0 63 0
[pid=12629] ppid=12611 vsize=162532 CPUtime=2.7
/proc/12629/stat : 12629 (clasp) R 12611 12611 1745 0 -1 4202496 48293 0 0 0 257 13 0 0 20 0 1 0 117973687 166432768 39778 18446744073709551615 4194304 6238623 140733450831904 140733450828928 4635076 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/12629/statm: 40633 39778 264 500 0 40130 0
[pid=12630] ppid=12611 vsize=22040 CPUtime=0
/proc/12630/stat : 12630 (parse.py) S 12611 12611 1745 0 -1 4202496 1319 0 0 0 0 0 0 0 20 0 1 0 117973687 22568960 1129 18446744073709551615 4194304 6642060 140734287703696 140734287702056 140346467407648 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/12630/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 15.89
Current children cumulated vsize (KiB) 193784

Child status: 0
Real time (s): 16.2786
CPU time (s): 15.997
CPU user time (s): 14.8769
CPU system time (s): 1.12007
CPU usage (%): 98.27
Max. virtual memory (cumulated for all children) (KiB): 587916

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 14.8769
system time used= 1.12007
maximum resident set size= 469600
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 231500
page faults= 10
swaps= 0
block input operations= 69088
block output operations= 65600
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 84
involuntary context switches= 1898

runsolver used 0.040002 second user time and 0.068004 second system time

The end