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/aspuncud-full-1.7/dist-upgrade/upgrade/difficult/rand196.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/upgrade/difficult/rand196.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/dist-upgrade/upgrade/difficult/rand196.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.00 1.02 1.00 2/59 30773
/proc/meminfo: memFree=306640/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9204 CPUtime=0
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 433 0 0 0 0 0 0 0 20 0 1 0 118036679 9424896 332 18446744073709551615 4194304 5129932 140734744230656 140734744228120 140535778387744 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2301 332 272 229 0 61 0

[startup+0.159127 s]
/proc/loadavg: 1.00 1.02 1.00 2/59 30773
/proc/meminfo: memFree=306640/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9212 CPUtime=0.03
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 698 2815 0 0 0 0 3 0 20 0 1 0 118036679 9433088 365 18446744073709551615 4194304 5129932 140734744230656 140734744229312 140535778243678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200326 s]
/proc/loadavg: 1.00 1.02 1.00 2/59 30773
/proc/meminfo: memFree=306640/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9212 CPUtime=0.03
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 698 2815 0 0 0 0 3 0 20 0 1 0 118036679 9433088 365 18446744073709551615 4194304 5129932 140734744230656 140734744229312 140535778243678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300321 s]
/proc/loadavg: 1.00 1.02 1.00 2/59 30773
/proc/meminfo: memFree=306640/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9212 CPUtime=0.03
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 698 2815 0 0 0 0 3 0 20 0 1 0 118036679 9433088 365 18446744073709551615 4194304 5129932 140734744230656 140734744229312 140535778243678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700221 s]
/proc/loadavg: 1.00 1.02 1.00 2/59 30773
/proc/meminfo: memFree=306640/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9212 CPUtime=0.03
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 698 2815 0 0 0 0 3 0 20 0 1 0 118036679 9433088 365 18446744073709551615 4194304 5129932 140734744230656 140734744229312 140535778243678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50033 s]
/proc/loadavg: 1.00 1.02 1.00 2/61 30786
/proc/meminfo: memFree=271656/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9212 CPUtime=0.03
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 698 2815 0 0 0 0 3 0 20 0 1 0 118036679 9433088 365 18446744073709551615 4194304 5129932 140734744230656 140734744229312 140535778243678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2303 365 303 229 0 63 0
[pid=30786] ppid=30773 vsize=34560 CPUtime=1.23
/proc/30786/stat : 30786 (cudf2lp) R 30773 30773 1733 0 -1 4202496 9913 0 0 0 118 5 0 0 20 0 1 0 118036682 35389440 8179 18446744073709551615 4194304 5690517 140735140172320 140735140169688 4293191 0 0 16781316 0 0 0 0 17 0 0 0 21 0 0
/proc/30786/statm: 8640 8179 160 366 0 8271 0
Current children cumulated CPU time (s) 1.26
Current children cumulated vsize (KiB) 43772

[startup+3.10034 s]
/proc/loadavg: 1.00 1.02 1.00 2/61 30786
/proc/meminfo: memFree=238672/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9212 CPUtime=0.03
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 698 2815 0 0 0 0 3 0 20 0 1 0 118036679 9433088 365 18446744073709551615 4194304 5129932 140734744230656 140734744229312 140535778243678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2303 365 303 229 0 63 0
[pid=30786] ppid=30773 vsize=58112 CPUtime=2.63
/proc/30786/stat : 30786 (cudf2lp) R 30773 30773 1733 0 -1 4202496 17613 0 0 0 256 7 0 0 20 0 1 0 118036682 59506688 14214 18446744073709551615 4194304 5690517 140735140172320 140735140169960 4357493 0 0 16781316 0 0 0 0 17 0 0 0 41 0 0
/proc/30786/statm: 14528 14214 160 366 0 14159 0
Current children cumulated CPU time (s) 2.66
Current children cumulated vsize (KiB) 67324

[startup+6.30023 s]
/proc/loadavg: 1.00 1.02 1.00 2/61 30786
/proc/meminfo: memFree=135628/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9212 CPUtime=5.11
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 725 44093 0 0 0 0 484 27 20 0 1 0 118036679 9433088 365 18446744073709551615 4194304 5129932 140734744230656 140734744229312 140535778243678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 5.11
Current children cumulated vsize (KiB) 9212

[startup+12.7003 s]
/proc/loadavg: 1.00 1.02 1.00 2/61 30787
/proc/meminfo: memFree=9788/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9212 CPUtime=5.11
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 725 44093 0 0 0 0 484 27 20 0 1 0 118036679 9433088 365 18446744073709551615 4194304 5129932 140734744230656 140734744229312 140535778243678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2303 365 303 229 0 63 0
[pid=30787] ppid=30773 vsize=558604 CPUtime=6.9
/proc/30787/stat : 30787 (gringo) R 30773 30773 1733 0 -1 4202496 131557 0 0 0 649 41 0 0 20 0 1 0 118037236 572010496 113060 18446744073709551615 4194304 6531320 140735267703184 140735267699528 4595420 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/30787/statm: 139651 113060 282 571 0 139072 0
Current children cumulated CPU time (s) 12.01
Current children cumulated vsize (KiB) 567816

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

[startup+12.8005 s]
/proc/loadavg: 1.00 1.02 1.00 2/61 30787
/proc/meminfo: memFree=9788/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9212 CPUtime=5.11
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 725 44093 0 0 0 0 484 27 20 0 1 0 118036679 9433088 365 18446744073709551615 4194304 5129932 140734744230656 140734744229312 140535778243678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2303 365 303 229 0 63 0
[pid=30787] ppid=30773 vsize=576204 CPUtime=6.99
/proc/30787/stat : 30787 (gringo) R 30773 30773 1733 0 -1 4202496 135267 0 0 0 657 42 0 0 20 0 1 0 118037236 590032896 116770 18446744073709551615 4194304 6531320 140735267703184 140735267699640 4349795 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/30787/statm: 144051 116770 282 571 0 143472 0
Current children cumulated CPU time (s) 12.1
Current children cumulated vsize (KiB) 585416

[startup+14.4033 s]
/proc/loadavg: 1.00 1.02 1.00 2/62 30789
/proc/meminfo: memFree=339788/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9212 CPUtime=12.88
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 764 181917 0 0 0 0 1206 82 20 0 1 0 118036679 9433088 365 18446744073709551615 4194304 5129932 140734744230656 140734744228720 140535778243678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2303 365 303 229 0 63 0
[pid=30788] ppid=30773 vsize=160284 CPUtime=0.62
/proc/30788/stat : 30788 (unclasp) R 30773 30773 1733 0 -1 4202496 44658 0 1 0 50 12 0 0 20 0 1 0 118038038 164130816 38424 18446744073709551615 4194304 6012874 140737379459984 140737379456584 4357159 0 0 16781316 16386 0 0 0 17 0 0 0 14 0 0
/proc/30788/statm: 40071 38424 173 444 0 39619 0
[pid=30789] ppid=30773 vsize=22040 CPUtime=0.02
/proc/30789/stat : 30789 (parse.py) S 30773 30773 1733 0 -1 4202496 1306 0 13 0 2 0 0 0 20 0 1 0 118038038 22568960 1127 18446744073709551615 4194304 6642060 140733474309744 140733474308104 140484594353952 0 0 16777220 20994 0 0 0 17 0 0 0 34 0 0
/proc/30789/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 13.52
Current children cumulated vsize (KiB) 191536

[startup+14.8003 s]
/proc/loadavg: 1.00 1.02 1.00 2/62 30789
/proc/meminfo: memFree=339788/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9212 CPUtime=12.88
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 764 181917 0 0 0 0 1206 82 20 0 1 0 118036679 9433088 365 18446744073709551615 4194304 5129932 140734744230656 140734744228720 140535778243678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2303 365 303 229 0 63 0
[pid=30788] ppid=30773 vsize=173156 CPUtime=1.02
/proc/30788/stat : 30788 (unclasp) R 30773 30773 1733 0 -1 4202496 47939 0 1 0 89 13 0 0 20 0 1 0 118038038 177311744 41705 18446744073709551615 4194304 6012874 140737379459984 140737379459304 5256221 0 0 16781316 16386 0 0 0 17 0 0 0 14 0 0
/proc/30788/statm: 43289 41705 218 444 0 42837 0
[pid=30789] ppid=30773 vsize=22040 CPUtime=0.02
/proc/30789/stat : 30789 (parse.py) S 30773 30773 1733 0 -1 4202496 1306 0 13 0 2 0 0 0 20 0 1 0 118038038 22568960 1127 18446744073709551615 4194304 6642060 140733474309744 140733474308104 140484594353952 0 0 16777220 20994 0 0 0 17 0 0 0 34 0 0
/proc/30789/statm: 5510 1127 508 598 0 596 0
Current children cumulated CPU time (s) 13.92
Current children cumulated vsize (KiB) 204408

[startup+15.0003 s]
/proc/loadavg: 1.00 1.02 1.00 2/62 30789
/proc/meminfo: memFree=339788/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9212 CPUtime=12.88
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 764 181917 0 0 0 0 1206 82 20 0 1 0 118036679 9433088 365 18446744073709551615 4194304 5129932 140734744230656 140734744228720 140535778243678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2303 365 303 229 0 63 0
[pid=30788] ppid=30773 vsize=160852 CPUtime=1.22
/proc/30788/stat : 30788 (unclasp) R 30773 30773 1733 0 -1 4202496 47948 0 1 0 108 14 0 0 20 0 1 0 118038038 164712448 39406 18446744073709551615 4194304 6012874 140737379459984 140737379459000 5182967 0 0 16781316 16386 0 0 0 17 0 0 0 14 0 0
/proc/30788/statm: 40213 39406 226 444 0 39761 0
[pid=30789] ppid=30773 vsize=22332 CPUtime=0.02
/proc/30789/stat : 30789 (parse.py) S 30773 30773 1733 0 -1 4202496 1350 0 13 0 2 0 0 0 20 0 1 0 118038038 22867968 1171 18446744073709551615 4194304 6642060 140733474309744 140733474307704 140484594353952 0 0 16777220 20994 0 0 0 17 0 0 0 34 0 0
/proc/30789/statm: 5583 1171 508 598 0 669 0
Current children cumulated CPU time (s) 14.12
Current children cumulated vsize (KiB) 192396

[startup+15.1014 s]
/proc/loadavg: 1.00 1.02 1.00 2/62 30789
/proc/meminfo: memFree=339788/1022884 swapFree=0/0
[pid=30773] ppid=30772 vsize=9212 CPUtime=12.88
/proc/30773/stat : 30773 (aspuncud-full) S 30772 30773 1733 0 -1 4202496 764 181917 0 0 0 0 1206 82 20 0 1 0 118036679 9433088 365 18446744073709551615 4194304 5129932 140734744230656 140734744228720 140535778243678 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/30773/statm: 2303 365 303 229 0 63 0
[pid=30788] ppid=30773 vsize=85204 CPUtime=1.32
/proc/30788/stat : 30788 (unclasp) R 30773 30773 1733 0 -1 4202496 47956 0 1 0 116 16 0 0 20 0 1 0 118038038 87248896 18999 18446744073709551615 4194304 6012874 140737379459984 140737379459384 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 14 0 0
/proc/30788/statm: 21301 18999 234 444 0 20849 0
[pid=30789] ppid=30773 vsize=22332 CPUtime=0.02
/proc/30789/stat : 30789 (parse.py) S 30773 30773 1733 0 -1 4202496 1377 0 13 0 2 0 0 0 20 0 1 0 118038038 22867968 1198 18446744073709551615 4194304 6642060 140733474309744 140733474307944 140484594353952 0 0 16777220 20994 0 0 0 17 0 0 0 34 0 0
/proc/30789/statm: 5583 1198 508 598 0 669 0
Current children cumulated CPU time (s) 14.22
Current children cumulated vsize (KiB) 116748

Child status: 0
Real time (s): 15.1444
CPU time (s): 14.2969
CPU user time (s): 13.2568
CPU system time (s): 1.04006
CPU usage (%): 94.404
Max. virtual memory (cumulated for all children) (KiB): 596232

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.2568
system time used= 1.04007
maximum resident set size= 477292
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 232299
page faults= 15
swaps= 0
block input operations= 82448
block output operations= 66328
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 231
involuntary context switches= 1938

runsolver used 0.024001 second user time and 0.068004 second system time

The end