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/rand874.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/upgrade/difficult/rand874.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/dist-upgrade/upgrade/difficult/rand874.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

[startup+0 s]
/proc/loadavg: 1.02 1.05 1.05 2/64 13583
/proc/meminfo: memFree=510572/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=3152 CPUtime=0
/proc/13583/stat : 13583 (runsolver) R 13582 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 118040776 3227648 32 18446744073709551615 134512640 134586868 4292180000 4292178048 4152136752 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.153227 s]
/proc/loadavg: 1.02 1.05 1.05 2/64 13583
/proc/meminfo: memFree=510572/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=9212 CPUtime=0.02
/proc/13583/stat : 13583 (aspuncud-full) S 13582 13583 1745 0 -1 4202496 694 2816 0 0 0 0 2 0 20 0 1 0 118040776 9433088 364 18446744073709551615 4194304 5129932 140734828756240 140734828754896 139796690723934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200328 s]
/proc/loadavg: 1.02 1.05 1.05 2/64 13583
/proc/meminfo: memFree=510572/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=9212 CPUtime=0.02
/proc/13583/stat : 13583 (aspuncud-full) S 13582 13583 1745 0 -1 4202496 694 2816 0 0 0 0 2 0 20 0 1 0 118040776 9433088 364 18446744073709551615 4194304 5129932 140734828756240 140734828754896 139796690723934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.30031 s]
/proc/loadavg: 1.02 1.05 1.05 2/64 13583
/proc/meminfo: memFree=510572/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=9212 CPUtime=0.02
/proc/13583/stat : 13583 (aspuncud-full) S 13582 13583 1745 0 -1 4202496 694 2816 0 0 0 0 2 0 20 0 1 0 118040776 9433088 364 18446744073709551615 4194304 5129932 140734828756240 140734828754896 139796690723934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700225 s]
/proc/loadavg: 1.02 1.05 1.05 2/64 13583
/proc/meminfo: memFree=510572/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=9212 CPUtime=0.02
/proc/13583/stat : 13583 (aspuncud-full) S 13582 13583 1745 0 -1 4202496 694 2816 0 0 0 0 2 0 20 0 1 0 118040776 9433088 364 18446744073709551615 4194304 5129932 140734828756240 140734828754896 139796690723934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50032 s]
/proc/loadavg: 1.02 1.05 1.05 2/66 13596
/proc/meminfo: memFree=474464/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=9212 CPUtime=0.02
/proc/13583/stat : 13583 (aspuncud-full) S 13582 13583 1745 0 -1 4202496 694 2816 0 0 0 0 2 0 20 0 1 0 118040776 9433088 364 18446744073709551615 4194304 5129932 140734828756240 140734828754896 139796690723934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 2303 364 303 229 0 63 0
[pid=13596] ppid=13583 vsize=54608 CPUtime=1.41
/proc/13596/stat : 13596 (cudf2lp) R 13583 13583 1745 0 -1 4202496 12733 0 0 0 132 9 0 0 20 0 1 0 118040779 55918592 10999 18446744073709551615 4194304 5690517 140733445007760 140733445003960 4371122 0 0 16781316 0 0 0 0 17 0 0 0 4 0 0
/proc/13596/statm: 13652 10999 160 366 0 13283 0
Current children cumulated CPU time (s) 1.43
Current children cumulated vsize (KiB) 63820

[startup+3.10032 s]
/proc/loadavg: 1.02 1.05 1.05 2/66 13596
/proc/meminfo: memFree=437760/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=9212 CPUtime=0.02
/proc/13583/stat : 13583 (aspuncud-full) S 13582 13583 1745 0 -1 4202496 694 2816 0 0 0 0 2 0 20 0 1 0 118040776 9433088 364 18446744073709551615 4194304 5129932 140734828756240 140734828754896 139796690723934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 2303 364 303 229 0 63 0
[pid=13596] ppid=13583 vsize=99144 CPUtime=2.86
/proc/13596/stat : 13596 (cudf2lp) R 13583 13583 1745 0 -1 4202496 28558 0 0 0 270 16 0 0 20 0 1 0 118040779 101523456 21830 18446744073709551615 4194304 5690517 140733445007760 140733445005400 4970538 0 0 16781316 0 0 0 0 17 0 0 0 18 0 0
/proc/13596/statm: 24786 21830 160 366 0 24417 0
Current children cumulated CPU time (s) 2.88
Current children cumulated vsize (KiB) 108356

[startup+6.30032 s]
/proc/loadavg: 1.02 1.05 1.05 2/66 13597
/proc/meminfo: memFree=440116/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=9212 CPUtime=4.51
/proc/13583/stat : 13583 (aspuncud-full) S 13582 13583 1745 0 -1 4202496 721 44094 0 0 0 0 418 33 20 0 1 0 118040776 9433088 364 18446744073709551615 4194304 5129932 140734828756240 140734828754896 139796690723934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 2303 364 303 229 0 63 0
[pid=13597] ppid=13583 vsize=42836 CPUtime=1.53
/proc/13597/stat : 13597 (gringo) R 13583 13583 1745 0 -1 4202496 12554 0 0 0 149 4 0 0 20 0 1 0 118041250 43864064 9421 18446744073709551615 4194304 6531320 140734287460560 140734287457176 4372275 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13597/statm: 10709 9421 259 571 0 10130 0
Current children cumulated CPU time (s) 6.04
Current children cumulated vsize (KiB) 52048

[startup+12.7003 s]
/proc/loadavg: 1.02 1.04 1.05 2/66 13597
/proc/meminfo: memFree=9168/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=9212 CPUtime=4.51
/proc/13583/stat : 13583 (aspuncud-full) S 13582 13583 1745 0 -1 4202496 721 44094 0 0 0 0 418 33 20 0 1 0 118040776 9433088 364 18446744073709551615 4194304 5129932 140734828756240 140734828754896 139796690723934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 2303 364 303 229 0 63 0
[pid=13597] ppid=13583 vsize=578644 CPUtime=7.79
/proc/13597/stat : 13597 (gringo) R 13583 13583 1745 0 -1 4202496 135658 0 0 0 731 48 0 0 20 0 1 0 118041250 592531456 117161 18446744073709551615 4194304 6531320 140734287460560 140734287456984 4452672 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/13597/statm: 144661 117161 282 571 0 144082 0
Current children cumulated CPU time (s) 12.3
Current children cumulated vsize (KiB) 587856

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

[startup+12.8004 s]
/proc/loadavg: 1.02 1.04 1.05 2/66 13597
/proc/meminfo: memFree=9168/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=9212 CPUtime=4.51
/proc/13583/stat : 13583 (aspuncud-full) S 13582 13583 1745 0 -1 4202496 721 44094 0 0 0 0 418 33 20 0 1 0 118040776 9433088 364 18446744073709551615 4194304 5129932 140734828756240 140734828754896 139796690723934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 2303 364 303 229 0 63 0
[pid=13597] ppid=13583 vsize=587816 CPUtime=7.87
/proc/13597/stat : 13597 (gringo) R 13583 13583 1745 0 -1 4202496 137869 0 0 0 739 48 0 0 20 0 1 0 118041250 601923584 119372 18446744073709551615 4194304 6531320 140734287460560 140734287456424 4345104 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/13597/statm: 146954 119372 282 571 0 146375 0
Current children cumulated CPU time (s) 12.38
Current children cumulated vsize (KiB) 597028

[startup+14.4074 s]
/proc/loadavg: 1.02 1.04 1.05 2/67 13599
/proc/meminfo: memFree=464888/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=9212 CPUtime=13.63
/proc/13583/stat : 13583 (aspuncud-full) S 13582 13583 1745 0 -1 4202496 760 187142 0 0 0 0 1261 102 20 0 1 0 118040776 9433088 364 18446744073709551615 4194304 5129932 140734828756240 140734828754304 139796690723934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 2303 364 303 229 0 63 0
[pid=13598] ppid=13583 vsize=63800 CPUtime=0.27
/proc/13598/stat : 13598 (unclasp) R 13583 13583 1745 0 -1 4202496 17727 0 0 0 19 8 0 0 20 0 1 0 118042187 65331200 14911 18446744073709551615 4194304 6012874 140735888251728 140735888248328 4416136 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13598/statm: 15950 14911 173 444 0 15498 0
[pid=13599] ppid=13583 vsize=22040 CPUtime=0.02
/proc/13599/stat : 13599 (parse.py) S 13583 13583 1745 0 -1 4202496 1320 0 0 0 1 1 0 0 20 0 1 0 118042187 22568960 1129 18446744073709551615 4194304 6642060 140736235081744 140736235080104 139924597290784 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13599/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 13.92
Current children cumulated vsize (KiB) 95052

[startup+15.2004 s]
/proc/loadavg: 1.02 1.04 1.05 2/67 13599
/proc/meminfo: memFree=464888/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=9212 CPUtime=13.63
/proc/13583/stat : 13583 (aspuncud-full) S 13582 13583 1745 0 -1 4202496 760 187142 0 0 0 0 1261 102 20 0 1 0 118040776 9433088 364 18446744073709551615 4194304 5129932 140734828756240 140734828754304 139796690723934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 2303 364 303 229 0 63 0
[pid=13598] ppid=13583 vsize=174688 CPUtime=1.05
/proc/13598/stat : 13598 (unclasp) R 13583 13583 1745 0 -1 4202496 48473 0 0 0 85 20 0 0 20 0 1 0 118042187 178880512 42238 18446744073709551615 4194304 6012874 140735888251728 140735888250488 4633888 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13598/statm: 43672 42238 186 444 0 43220 0
[pid=13599] ppid=13583 vsize=22040 CPUtime=0.02
/proc/13599/stat : 13599 (parse.py) S 13583 13583 1745 0 -1 4202496 1320 0 0 0 1 1 0 0 20 0 1 0 118042187 22568960 1129 18446744073709551615 4194304 6642060 140736235081744 140736235080104 139924597290784 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13599/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 14.7
Current children cumulated vsize (KiB) 205940

[startup+15.6003 s]
/proc/loadavg: 1.02 1.04 1.05 2/67 13599
/proc/meminfo: memFree=334564/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=9212 CPUtime=13.63
/proc/13583/stat : 13583 (aspuncud-full) S 13582 13583 1745 0 -1 4202496 760 187142 0 0 0 0 1261 102 20 0 1 0 118040776 9433088 364 18446744073709551615 4194304 5129932 140734828756240 140734828754304 139796690723934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 2303 364 303 229 0 63 0
[pid=13598] ppid=13583 vsize=181500 CPUtime=1.44
/proc/13598/stat : 13598 (unclasp) R 13583 13583 1745 0 -1 4202496 50230 0 0 0 124 20 0 0 20 0 1 0 118042187 185856000 43995 18446744073709551615 4194304 6012874 140735888251728 140735888250792 5256141 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13598/statm: 45375 43995 225 444 0 44923 0
[pid=13599] ppid=13583 vsize=22188 CPUtime=0.02
/proc/13599/stat : 13599 (parse.py) S 13583 13583 1745 0 -1 4202496 1335 0 0 0 1 1 0 0 20 0 1 0 118042187 22720512 1144 18446744073709551615 4194304 6642060 140736235081744 140736235079704 139924597290784 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13599/statm: 5547 1144 508 598 0 633 0
Current children cumulated CPU time (s) 15.09
Current children cumulated vsize (KiB) 212900

[startup+15.8003 s]
/proc/loadavg: 1.02 1.04 1.05 2/67 13599
/proc/meminfo: memFree=334564/1022884 swapFree=0/0
[pid=13583] ppid=13582 vsize=9212 CPUtime=13.63
/proc/13583/stat : 13583 (aspuncud-full) S 13582 13583 1745 0 -1 4202496 760 187142 0 0 0 0 1261 102 20 0 1 0 118040776 9433088 364 18446744073709551615 4194304 5129932 140734828756240 140734828754304 139796690723934 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13583/statm: 2303 364 303 229 0 63 0
[pid=13598] ppid=13583 vsize=169196 CPUtime=1.64
/proc/13598/stat : 13598 (unclasp) R 13583 13583 1745 0 -1 4202496 50230 0 0 0 144 20 0 0 20 0 1 0 118042187 173256704 41567 18446744073709551615 4194304 6012874 140735888251728 140735888250792 4530494 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13598/statm: 42299 41567 225 444 0 41847 0
[pid=13599] ppid=13583 vsize=22368 CPUtime=0.02
/proc/13599/stat : 13599 (parse.py) S 13583 13583 1745 0 -1 4202496 1373 0 0 0 1 1 0 0 20 0 1 0 118042187 22904832 1182 18446744073709551615 4194304 6642060 140736235081744 140736235079832 139924597290784 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13599/statm: 5592 1182 508 598 0 678 0
Current children cumulated CPU time (s) 15.29
Current children cumulated vsize (KiB) 200776

Child status: 0
Real time (s): 15.8946
CPU time (s): 15.413
CPU user time (s): 14.1089
CPU system time (s): 1.30408
CPU usage (%): 96.9696
Max. virtual memory (cumulated for all children) (KiB): 620508

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 14.1089
system time used= 1.30408
maximum resident set size= 498188
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 239800
page faults= 0
swaps= 0
block input operations= 68432
block output operations= 69072
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 126
involuntary context switches= 1899

runsolver used 0.024001 second user time and 0.084005 second system time

The end