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/rand293.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/upgrade/difficult/rand293.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/dist-upgrade/upgrade/difficult/rand293.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.04 1.05 1.06 2/64 13539
/proc/meminfo: memFree=470632/1022884 swapFree=0/0
[pid=13539] ppid=13538 vsize=1068 CPUtime=0
/proc/13539/stat : 13539 (aspuncud-full) D 13538 13539 1745 0 -1 4194304 75 0 0 0 0 0 0 0 20 0 1 0 118036795 1093632 1 18446744073709551615 0 0 140734364277665 4287446688 4151878704 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/13539/statm: 267 1 0 0 0 28 0

[startup+0.193127 s]
/proc/loadavg: 1.04 1.05 1.06 2/64 13539
/proc/meminfo: memFree=470632/1022884 swapFree=0/0
[pid=13539] ppid=13538 vsize=9212 CPUtime=0.02
/proc/13539/stat : 13539 (aspuncud-full) S 13538 13539 1745 0 -1 4202496 696 2805 2 7 0 0 1 1 20 0 1 0 118036795 9433088 365 18446744073709551615 4194304 5129932 140734364273200 140734364271856 140011324077150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13539/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200286 s]
/proc/loadavg: 1.04 1.05 1.06 2/64 13539
/proc/meminfo: memFree=470632/1022884 swapFree=0/0
[pid=13539] ppid=13538 vsize=9212 CPUtime=0.02
/proc/13539/stat : 13539 (aspuncud-full) S 13538 13539 1745 0 -1 4202496 696 2805 2 7 0 0 1 1 20 0 1 0 118036795 9433088 365 18446744073709551615 4194304 5129932 140734364273200 140734364271856 140011324077150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13539/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300268 s]
/proc/loadavg: 1.04 1.05 1.06 2/64 13539
/proc/meminfo: memFree=470632/1022884 swapFree=0/0
[pid=13539] ppid=13538 vsize=9212 CPUtime=0.02
/proc/13539/stat : 13539 (aspuncud-full) S 13538 13539 1745 0 -1 4202496 696 2805 2 7 0 0 1 1 20 0 1 0 118036795 9433088 365 18446744073709551615 4194304 5129932 140734364273200 140734364271856 140011324077150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13539/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700356 s]
/proc/loadavg: 1.04 1.05 1.06 2/64 13539
/proc/meminfo: memFree=470632/1022884 swapFree=0/0
[pid=13539] ppid=13538 vsize=9212 CPUtime=0.02
/proc/13539/stat : 13539 (aspuncud-full) S 13538 13539 1745 0 -1 4202496 696 2805 2 7 0 0 1 1 20 0 1 0 118036795 9433088 365 18446744073709551615 4194304 5129932 140734364273200 140734364271856 140011324077150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13539/statm: 2303 365 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.04 1.05 1.06 1/66 13552
/proc/meminfo: memFree=433160/1022884 swapFree=0/0
[pid=13539] ppid=13538 vsize=9212 CPUtime=0.02
/proc/13539/stat : 13539 (aspuncud-full) S 13538 13539 1745 0 -1 4202496 696 2805 2 7 0 0 1 1 20 0 1 0 118036795 9433088 365 18446744073709551615 4194304 5129932 140734364273200 140734364271856 140011324077150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13539/statm: 2303 365 303 229 0 63 0
[pid=13552] ppid=13539 vsize=53756 CPUtime=1.28
/proc/13552/stat : 13552 (cudf2lp) R 13539 13539 1745 0 -1 4202496 14927 0 1 0 118 10 0 0 20 0 1 0 118036806 55046144 11528 18446744073709551615 4194304 5690517 140734792172416 140734792170056 4956092 0 0 16781316 0 0 0 0 17 0 0 0 9 0 0
/proc/13552/statm: 13439 11528 160 366 0 13070 0
Current children cumulated CPU time (s) 1.3
Current children cumulated vsize (KiB) 62968

[startup+3.10034 s]
/proc/loadavg: 1.04 1.05 1.06 2/66 13552
/proc/meminfo: memFree=398440/1022884 swapFree=0/0
[pid=13539] ppid=13538 vsize=9212 CPUtime=0.02
/proc/13539/stat : 13539 (aspuncud-full) S 13538 13539 1745 0 -1 4202496 696 2805 2 7 0 0 1 1 20 0 1 0 118036795 9433088 365 18446744073709551615 4194304 5129932 140734364273200 140734364271856 140011324077150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13539/statm: 2303 365 303 229 0 63 0
[pid=13552] ppid=13539 vsize=99144 CPUtime=2.75
/proc/13552/stat : 13552 (cudf2lp) R 13539 13539 1745 0 -1 4202496 28311 0 1 0 260 15 0 0 20 0 1 0 118036806 101523456 21583 18446744073709551615 4194304 5690517 140734792172416 140734792170056 4443939 0 0 16781316 0 0 0 0 17 0 0 0 21 0 0
/proc/13552/statm: 24786 21583 160 366 0 24417 0
Current children cumulated CPU time (s) 2.77
Current children cumulated vsize (KiB) 108356

[startup+6.30026 s]
/proc/loadavg: 1.04 1.05 1.06 2/66 13553
/proc/meminfo: memFree=411832/1022884 swapFree=0/0
[pid=13539] ppid=13538 vsize=9212 CPUtime=4.82
/proc/13539/stat : 13539 (aspuncud-full) S 13538 13539 1745 0 -1 4202496 723 44083 2 8 0 0 446 36 20 0 1 0 118036795 9433088 365 18446744073709551615 4194304 5129932 140734364273200 140734364271856 140011324077150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13539/statm: 2303 365 303 229 0 63 0
[pid=13553] ppid=13539 vsize=40844 CPUtime=1.09
/proc/13553/stat : 13553 (gringo) R 13539 13539 1745 0 -1 4202496 11588 0 1 0 98 11 0 0 20 0 1 0 118037313 41824256 8456 18446744073709551615 4194304 6531320 140734240705568 140734240701384 4372767 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/13553/statm: 10211 8456 259 571 0 9632 0
Current children cumulated CPU time (s) 5.91
Current children cumulated vsize (KiB) 50056

[startup+12.7003 s]
/proc/loadavg: 1.03 1.05 1.05 2/67 13555
/proc/meminfo: memFree=432528/1022884 swapFree=0/0
[pid=13539] ppid=13538 vsize=9212 CPUtime=11.42
/proc/13539/stat : 13539 (aspuncud-full) S 13538 13539 1745 0 -1 4202496 762 179647 2 9 0 0 1045 97 20 0 1 0 118036795 9433088 365 18446744073709551615 4194304 5129932 140734364273200 140734364271264 140011324077150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13539/statm: 2303 365 303 229 0 63 0
[pid=13554] ppid=13539 vsize=165276 CPUtime=0.72
/proc/13554/stat : 13554 (unclasp) R 13539 13539 1745 0 -1 4202496 45830 0 0 0 57 15 0 0 20 0 1 0 118037990 169242624 39595 18446744073709551615 4194304 6012874 140736687733088 140736687731576 4630037 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13554/statm: 41319 39595 188 444 0 40867 0
[pid=13555] ppid=13539 vsize=22040 CPUtime=0.01
/proc/13555/stat : 13555 (parse.py) S 13539 13539 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 118037990 22568960 1128 18446744073709551615 4194304 6642060 140736738434224 140736738432584 139863406106400 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/13555/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.15
Current children cumulated vsize (KiB) 196528

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

[startup+12.8004 s]
/proc/loadavg: 1.03 1.05 1.05 2/67 13555
/proc/meminfo: memFree=432528/1022884 swapFree=0/0
[pid=13539] ppid=13538 vsize=9212 CPUtime=11.42
/proc/13539/stat : 13539 (aspuncud-full) S 13538 13539 1745 0 -1 4202496 762 179647 2 9 0 0 1045 97 20 0 1 0 118036795 9433088 365 18446744073709551615 4194304 5129932 140734364273200 140734364271264 140011324077150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13539/statm: 2303 365 303 229 0 63 0
[pid=13554] ppid=13539 vsize=170008 CPUtime=0.82
/proc/13554/stat : 13554 (unclasp) R 13539 13539 1745 0 -1 4202496 47006 0 0 0 66 16 0 0 20 0 1 0 118037990 174088192 40771 18446744073709551615 4194304 6012874 140736687733088 140736687731848 4350085 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13554/statm: 42502 40771 199 444 0 42050 0
[pid=13555] ppid=13539 vsize=22040 CPUtime=0.01
/proc/13555/stat : 13555 (parse.py) S 13539 13539 1745 0 -1 4202496 1320 0 0 0 1 0 0 0 20 0 1 0 118037990 22568960 1128 18446744073709551615 4194304 6642060 140736738434224 140736738432584 139863406106400 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/13555/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.25
Current children cumulated vsize (KiB) 201260

[startup+13.0003 s]
/proc/loadavg: 1.03 1.05 1.05 2/67 13555
/proc/meminfo: memFree=432528/1022884 swapFree=0/0
[pid=13539] ppid=13538 vsize=9212 CPUtime=11.42
/proc/13539/stat : 13539 (aspuncud-full) S 13538 13539 1745 0 -1 4202496 762 179647 2 9 0 0 1045 97 20 0 1 0 118036795 9433088 365 18446744073709551615 4194304 5129932 140734364273200 140734364271264 140011324077150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13539/statm: 2303 365 303 229 0 63 0
[pid=13554] ppid=13539 vsize=157704 CPUtime=1.02
/proc/13554/stat : 13554 (unclasp) R 13539 13539 1745 0 -1 4202496 47062 0 0 0 86 16 0 0 20 0 1 0 118037990 161488896 38564 18446744073709551615 4194304 6012874 140736687733088 140736687732264 4539063 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13554/statm: 39426 38564 225 444 0 38974 0
[pid=13555] ppid=13539 vsize=22188 CPUtime=0.01
/proc/13555/stat : 13555 (parse.py) S 13539 13539 1745 0 -1 4202496 1333 0 0 0 1 0 0 0 20 0 1 0 118037990 22720512 1141 18446744073709551615 4194304 6642060 140736738434224 140736738432232 139863406106400 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/13555/statm: 5547 1141 508 598 0 633 0
Current children cumulated CPU time (s) 12.45
Current children cumulated vsize (KiB) 189104

[startup+13.1004 s]
/proc/loadavg: 1.03 1.05 1.05 2/67 13555
/proc/meminfo: memFree=432528/1022884 swapFree=0/0
[pid=13539] ppid=13538 vsize=9212 CPUtime=11.42
/proc/13539/stat : 13539 (aspuncud-full) S 13538 13539 1745 0 -1 4202496 762 179647 2 9 0 0 1045 97 20 0 1 0 118036795 9433088 365 18446744073709551615 4194304 5129932 140734364273200 140734364271264 140011324077150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/13539/statm: 2303 365 303 229 0 63 0
[pid=13554] ppid=13539 vsize=157704 CPUtime=1.11
/proc/13554/stat : 13554 (unclasp) R 13539 13539 1745 0 -1 4202496 47071 0 0 0 92 19 0 0 20 0 1 0 118037990 161488896 19117 18446744073709551615 4194304 6012874 140736687733088 140736687732488 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13554/statm: 39426 19117 234 444 0 38974 0
[pid=13555] ppid=13539 vsize=22332 CPUtime=0.02
/proc/13555/stat : 13555 (parse.py) S 13539 13539 1745 0 -1 4202496 1367 0 0 0 2 0 0 0 20 0 1 0 118037990 22867968 1175 18446744073709551615 4194304 6642060 140736738434224 140736738432392 139863406106400 0 0 16777220 20994 0 0 0 17 0 0 0 8 0 0
/proc/13555/statm: 5583 1175 508 598 0 669 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 189248

Child status: 0
Real time (s): 13.1484
CPU time (s): 12.6208
CPU user time (s): 11.4207
CPU system time (s): 1.20007
CPU usage (%): 95.9874
Max. virtual memory (cumulated for all children) (KiB): 586896

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 11.4207
system time used= 1.20008
maximum resident set size= 468256
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 229134
page faults= 11
swaps= 0
block input operations= 69232
block output operations= 65312
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 158
involuntary context switches= 1583

runsolver used 0.032002 second user time and 0.056003 second system time

The end