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/rand491.cudf.log.runsolver /home/competition/aspcud-full-1.7/aspcud-full /home/competition/data/upgrade/difficult/rand491.cudf /tmp/misc2012/2012-09-02-22:42/full/aspcud-full-1.7/dist-upgrade/upgrade/difficult/rand491.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.16 1.11 1.08 2/64 12636
/proc/meminfo: memFree=512924/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=3152 CPUtime=0
/proc/12636/stat : 12636 (runsolver) R 12635 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 117974698 3227648 33 18446744073709551615 134512640 134586868 4290655344 4290653392 4151465008 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 788 33 0 19 0 73 0

[startup+0.144442 s]
/proc/loadavg: 1.16 1.11 1.08 2/64 12636
/proc/meminfo: memFree=512924/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=0.03
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 734 3624 0 0 0 0 2 1 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224608 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200273 s]
/proc/loadavg: 1.16 1.11 1.08 2/64 12636
/proc/meminfo: memFree=512924/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=0.03
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 734 3624 0 0 0 0 2 1 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224608 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300249 s]
/proc/loadavg: 1.16 1.11 1.08 2/64 12636
/proc/meminfo: memFree=512924/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=0.03
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 734 3624 0 0 0 0 2 1 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224608 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.70023 s]
/proc/loadavg: 1.16 1.11 1.08 2/64 12636
/proc/meminfo: memFree=512924/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=0.03
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 734 3624 0 0 0 0 2 1 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224608 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50027 s]
/proc/loadavg: 1.15 1.11 1.08 2/66 12652
/proc/meminfo: memFree=471980/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=0.03
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 734 3624 0 0 0 0 2 1 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224608 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
[pid=12652] ppid=12636 vsize=53756 CPUtime=1.37
/proc/12652/stat : 12652 (cudf2lp) R 12636 12636 1745 0 -1 4202496 15321 0 0 0 130 7 0 0 20 0 1 0 117974701 55046144 11923 18446744073709551615 4194304 5690517 140734325123584 140734325121224 4348960 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/12652/statm: 13439 11923 160 366 0 13070 0
Current children cumulated CPU time (s) 1.4
Current children cumulated vsize (KiB) 62968

[startup+3.10033 s]
/proc/loadavg: 1.15 1.11 1.08 2/66 12652
/proc/meminfo: memFree=433540/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=0.03
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 734 3624 0 0 0 0 2 1 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224608 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
[pid=12652] ppid=12636 vsize=99144 CPUtime=2.85
/proc/12652/stat : 12652 (cudf2lp) R 12636 12636 1745 0 -1 4202496 28648 0 0 0 273 12 0 0 20 0 1 0 117974701 101523456 21921 18446744073709551615 4194304 5690517 140734325123584 140734325121224 4334638 0 0 16781316 0 0 0 0 17 0 0 0 19 0 0
/proc/12652/statm: 24786 21921 160 366 0 24417 0
Current children cumulated CPU time (s) 2.88
Current children cumulated vsize (KiB) 108356

[startup+6.30038 s]
/proc/loadavg: 1.15 1.11 1.08 2/66 12653
/proc/meminfo: memFree=446436/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=4.65
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 758 44901 0 0 0 0 436 29 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224608 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
[pid=12653] ppid=12636 vsize=40844 CPUtime=1.4
/proc/12653/stat : 12653 (gringo) R 12636 12636 1745 0 -1 4202496 11784 0 0 0 133 7 0 0 20 0 1 0 117975186 41824256 8651 18446744073709551615 4194304 6531320 140734077676400 140734077673016 4359104 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/12653/statm: 10211 8651 259 571 0 9632 0
Current children cumulated CPU time (s) 6.05
Current children cumulated vsize (KiB) 50056

[startup+12.7003 s]
/proc/loadavg: 1.12 1.10 1.08 2/66 12653
/proc/meminfo: memFree=90928/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=4.65
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 758 44901 0 0 0 0 436 29 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224608 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
[pid=12653] ppid=12636 vsize=512216 CPUtime=7.73
/proc/12653/stat : 12653 (gringo) R 12636 12636 1745 0 -1 4202496 121709 0 0 0 724 49 0 0 20 0 1 0 117975186 524509184 103212 18446744073709551615 4194304 6531320 140734077676400 140734077673016 4363203 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/12653/statm: 128054 103212 282 571 0 127475 0
Current children cumulated CPU time (s) 12.38
Current children cumulated vsize (KiB) 521428

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

[startup+12.8004 s]
/proc/loadavg: 1.12 1.10 1.08 2/66 12653
/proc/meminfo: memFree=90928/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=4.65
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 758 44901 0 0 0 0 436 29 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224608 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
[pid=12653] ppid=12636 vsize=513548 CPUtime=7.84
/proc/12653/stat : 12653 (gringo) R 12636 12636 1745 0 -1 4202496 121970 0 0 0 734 50 0 0 20 0 1 0 117975186 525873152 103473 18446744073709551615 4194304 6531320 140734077676400 140734077673016 5119461 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/12653/statm: 128387 103473 282 571 0 127808 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 522760

[startup+16.0004 s]
/proc/loadavg: 1.12 1.10 1.08 2/67 12655
/proc/meminfo: memFree=392080/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=14.42
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 795 183786 0 0 0 0 1342 100 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224016 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
[pid=12654] ppid=12636 vsize=169348 CPUtime=1.08
/proc/12654/stat : 12654 (clasp) R 12636 12636 1745 0 -1 4202496 46969 0 0 0 92 16 0 0 20 0 1 0 117976186 173412352 40733 18446744073709551615 4194304 6238623 140736076552736 140736076550072 4766479 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/12654/statm: 42337 40733 214 500 0 41834 0
[pid=12655] ppid=12636 vsize=22040 CPUtime=0.01
/proc/12655/stat : 12655 (parse.py) S 12636 12636 1745 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 117976186 22568960 1127 18446744073709551615 4194304 6642060 140735416820832 140735416819192 139997049202464 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/12655/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 15.51
Current children cumulated vsize (KiB) 200600

[startup+17.6004 s]
/proc/loadavg: 1.11 1.10 1.08 2/67 12655
/proc/meminfo: memFree=325120/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=14.42
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 795 183786 0 0 0 0 1342 100 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224016 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
[pid=12654] ppid=12636 vsize=166892 CPUtime=2.67
/proc/12654/stat : 12654 (clasp) R 12636 12636 1745 0 -1 4202496 49482 0 0 0 248 19 0 0 20 0 1 0 117976186 170897408 40910 18446744073709551615 4194304 6238623 140736076552736 140736076549760 4586251 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/12654/statm: 41723 40910 263 500 0 41220 0
[pid=12655] ppid=12636 vsize=22040 CPUtime=0.01
/proc/12655/stat : 12655 (parse.py) S 12636 12636 1745 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 117976186 22568960 1127 18446744073709551615 4194304 6642060 140735416820832 140735416819192 139997049202464 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/12655/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 17.1
Current children cumulated vsize (KiB) 198144

[startup+19.2004 s]
/proc/loadavg: 1.11 1.10 1.08 2/67 12655
/proc/meminfo: memFree=325120/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=14.42
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 795 183786 0 0 0 0 1342 100 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224016 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
[pid=12654] ppid=12636 vsize=166892 CPUtime=4.25
/proc/12654/stat : 12654 (clasp) R 12636 12636 1745 0 -1 4202496 49483 0 0 0 406 19 0 0 20 0 1 0 117976186 170897408 40911 18446744073709551615 4194304 6238623 140736076552736 140736076549760 4635535 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/12654/statm: 41723 40911 264 500 0 41220 0
[pid=12655] ppid=12636 vsize=22040 CPUtime=0.01
/proc/12655/stat : 12655 (parse.py) S 12636 12636 1745 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 117976186 22568960 1127 18446744073709551615 4194304 6642060 140735416820832 140735416819192 139997049202464 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/12655/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 18.68
Current children cumulated vsize (KiB) 198144

[startup+20.0004 s]
/proc/loadavg: 1.11 1.10 1.08 2/67 12655
/proc/meminfo: memFree=325120/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=14.42
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 795 183786 0 0 0 0 1342 100 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224016 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
[pid=12654] ppid=12636 vsize=166892 CPUtime=5.04
/proc/12654/stat : 12654 (clasp) R 12636 12636 1745 0 -1 4202496 49483 0 0 0 485 19 0 0 20 0 1 0 117976186 170897408 40911 18446744073709551615 4194304 6238623 140736076552736 140736076549760 4306653 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/12654/statm: 41723 40911 264 500 0 41220 0
[pid=12655] ppid=12636 vsize=22040 CPUtime=0.01
/proc/12655/stat : 12655 (parse.py) S 12636 12636 1745 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 117976186 22568960 1127 18446744073709551615 4194304 6642060 140735416820832 140735416819192 139997049202464 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/12655/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 19.47
Current children cumulated vsize (KiB) 198144

[startup+20.2004 s]
/proc/loadavg: 1.11 1.10 1.08 2/67 12655
/proc/meminfo: memFree=325120/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=14.42
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 795 183786 0 0 0 0 1342 100 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224016 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
[pid=12654] ppid=12636 vsize=166892 CPUtime=5.24
/proc/12654/stat : 12654 (clasp) R 12636 12636 1745 0 -1 4202496 49483 0 0 0 505 19 0 0 20 0 1 0 117976186 170897408 40911 18446744073709551615 4194304 6238623 140736076552736 140736076549760 4409923 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/12654/statm: 41723 40911 264 500 0 41220 0
[pid=12655] ppid=12636 vsize=22040 CPUtime=0.01
/proc/12655/stat : 12655 (parse.py) S 12636 12636 1745 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 117976186 22568960 1127 18446744073709551615 4194304 6642060 140735416820832 140735416819192 139997049202464 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/12655/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 19.67
Current children cumulated vsize (KiB) 198144

[startup+20.3004 s]
/proc/loadavg: 1.11 1.10 1.08 2/67 12655
/proc/meminfo: memFree=325120/1022884 swapFree=0/0
[pid=12636] ppid=12635 vsize=9212 CPUtime=14.42
/proc/12636/stat : 12636 (aspcud-full) S 12635 12636 1745 0 -1 4202496 795 183786 0 0 0 0 1342 100 20 0 1 0 117974698 9433088 365 18446744073709551615 4194304 5129932 140736688225952 140736688224016 139918853387358 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/12636/statm: 2303 365 303 229 0 63 0
[pid=12654] ppid=12636 vsize=166892 CPUtime=5.34
/proc/12654/stat : 12654 (clasp) R 12636 12636 1745 0 -1 4202496 49483 0 0 0 515 19 0 0 20 0 1 0 117976186 170897408 40911 18446744073709551615 4194304 6238623 140736076552736 140736076549760 4371507 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/12654/statm: 41723 40911 264 500 0 41220 0
[pid=12655] ppid=12636 vsize=22040 CPUtime=0.01
/proc/12655/stat : 12655 (parse.py) S 12636 12636 1745 0 -1 4202496 1317 0 0 0 1 0 0 0 20 0 1 0 117976186 22568960 1127 18446744073709551615 4194304 6642060 140735416820832 140735416819192 139997049202464 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/12655/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 19.77
Current children cumulated vsize (KiB) 198144

Child status: 0
Real time (s): 20.3798
CPU time (s): 19.8892
CPU user time (s): 18.6252
CPU system time (s): 1.26408
CPU usage (%): 97.5928
Max. virtual memory (cumulated for all children) (KiB): 599840

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 18.6252
system time used= 1.26408
maximum resident set size= 481536
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 235689
page faults= 0
swaps= 0
block input operations= 68440
block output operations= 66952
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 91
involuntary context switches= 2359

runsolver used 0.056003 second user time and 0.088005 second system time

The end