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/rand313.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/upgrade/difficult/rand313.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/dist-upgrade/upgrade/difficult/rand313.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.02 1.03 1.00 2/59 13739
/proc/meminfo: memFree=538552/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9204 CPUtime=0
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 430 0 0 0 0 0 0 0 20 0 1 0 118041352 9424896 331 18446744073709551615 4194304 5129932 140737351725424 140737351722888 140255488059168 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2301 331 272 229 0 61 0

[startup+0.113279 s]
/proc/loadavg: 1.02 1.03 1.00 2/59 13739
/proc/meminfo: memFree=538552/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9212 CPUtime=0.04
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 693 2811 0 0 0 0 3 1 20 0 1 0 118041352 9433088 364 18446744073709551615 4194304 5129932 140737351725424 140737351724080 140255487915102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200269 s]
/proc/loadavg: 1.02 1.03 1.00 2/59 13739
/proc/meminfo: memFree=538552/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9212 CPUtime=0.04
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 693 2811 0 0 0 0 3 1 20 0 1 0 118041352 9433088 364 18446744073709551615 4194304 5129932 140737351725424 140737351724080 140255487915102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300265 s]
/proc/loadavg: 1.02 1.03 1.00 2/59 13739
/proc/meminfo: memFree=538552/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9212 CPUtime=0.04
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 693 2811 0 0 0 0 3 1 20 0 1 0 118041352 9433088 364 18446744073709551615 4194304 5129932 140737351725424 140737351724080 140255487915102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700207 s]
/proc/loadavg: 1.02 1.03 1.00 2/59 13739
/proc/meminfo: memFree=538552/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9212 CPUtime=0.04
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 693 2811 0 0 0 0 3 1 20 0 1 0 118041352 9433088 364 18446744073709551615 4194304 5129932 140737351725424 140737351724080 140255487915102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50031 s]
/proc/loadavg: 1.01 1.03 1.00 2/61 13752
/proc/meminfo: memFree=482356/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9212 CPUtime=0.04
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 693 2811 0 0 0 0 3 1 20 0 1 0 118041352 9433088 364 18446744073709551615 4194304 5129932 140737351725424 140737351724080 140255487915102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2303 364 303 229 0 63 0
[pid=13752] ppid=13739 vsize=53756 CPUtime=1.38
/proc/13752/stat : 13752 (cudf2lp) R 13739 13739 1750 0 -1 4202496 15424 0 0 0 131 7 0 0 20 0 1 0 118041355 55046144 12025 18446744073709551615 4194304 5690517 140736142714336 140736142711976 4293647 0 0 16781316 0 0 0 0 17 0 0 0 7 0 0
/proc/13752/statm: 13439 12025 160 366 0 13070 0
Current children cumulated CPU time (s) 1.42
Current children cumulated vsize (KiB) 62968

[startup+3.10032 s]
/proc/loadavg: 1.01 1.03 1.00 3/61 13752
/proc/meminfo: memFree=460160/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9212 CPUtime=0.04
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 693 2811 0 0 0 0 3 1 20 0 1 0 118041352 9433088 364 18446744073709551615 4194304 5129932 140737351725424 140737351724080 140255487915102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2303 364 303 229 0 63 0
[pid=13752] ppid=13739 vsize=99144 CPUtime=2.96
/proc/13752/stat : 13752 (cudf2lp) R 13739 13739 1750 0 -1 4202496 28581 0 0 0 283 13 0 0 20 0 1 0 118041355 101523456 21853 18446744073709551615 4194304 5690517 140736142714336 140736142711976 4357520 0 0 16781316 0 0 0 0 17 0 0 0 8 0 0
/proc/13752/statm: 24786 21853 160 366 0 24417 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 108356

[startup+6.30033 s]
/proc/loadavg: 1.09 1.04 1.01 2/61 13753
/proc/meminfo: memFree=474420/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9212 CPUtime=4.88
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 720 44088 0 0 0 0 456 32 20 0 1 0 118041352 9433088 364 18446744073709551615 4194304 5129932 140737351725424 140737351724080 140255487915102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2303 364 303 229 0 63 0
[pid=13753] ppid=13739 vsize=39308 CPUtime=1.27
/proc/13753/stat : 13753 (gringo) R 13739 13739 1750 0 -1 4202496 11195 0 0 0 120 7 0 0 20 0 1 0 118041854 40251392 8062 18446744073709551615 4194304 6531320 140736006237840 140736006233640 4330140 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13753/statm: 9827 8062 259 571 0 9248 0
Current children cumulated CPU time (s) 6.15
Current children cumulated vsize (KiB) 48520

[startup+12.7003 s]
/proc/loadavg: 1.08 1.04 1.00 2/61 13753
/proc/meminfo: memFree=10004/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9212 CPUtime=4.88
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 720 44088 0 0 0 0 456 32 20 0 1 0 118041352 9433088 364 18446744073709551615 4194304 5129932 140737351725424 140737351724080 140255487915102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2303 364 303 229 0 63 0
[pid=13753] ppid=13739 vsize=671552 CPUtime=7.49
/proc/13753/stat : 13753 (gringo) R 13739 13739 1750 0 -1 4202496 155410 0 0 0 693 56 0 0 20 0 1 0 118041854 687669248 136913 18446744073709551615 4194304 6531320 140736006237840 140736006234600 4600134 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13753/statm: 167888 136913 283 571 0 167309 0
Current children cumulated CPU time (s) 12.37
Current children cumulated vsize (KiB) 680764

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

[startup+12.8003 s]
/proc/loadavg: 1.08 1.04 1.00 2/61 13753
/proc/meminfo: memFree=10004/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9212 CPUtime=4.88
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 720 44088 0 0 0 0 456 32 20 0 1 0 118041352 9433088 364 18446744073709551615 4194304 5129932 140737351725424 140737351724080 140255487915102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2303 364 303 229 0 63 0
[pid=13753] ppid=13739 vsize=671552 CPUtime=7.59
/proc/13753/stat : 13753 (gringo) R 13739 13739 1750 0 -1 4202496 155410 0 0 0 703 56 0 0 20 0 1 0 118041854 687669248 136913 18446744073709551615 4194304 6531320 140736006237840 140736006234600 5502304 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13753/statm: 167888 136913 283 571 0 167309 0
Current children cumulated CPU time (s) 12.47
Current children cumulated vsize (KiB) 680764

[startup+13.6002 s]
/proc/loadavg: 1.08 1.04 1.00 2/61 13753
/proc/meminfo: memFree=55832/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9212 CPUtime=13.09
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 759 199502 0 0 0 0 1207 102 20 0 1 0 118041352 9433088 364 18446744073709551615 4194304 5129932 140737351725424 140737351723488 140255487915102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 13.09
Current children cumulated vsize (KiB) 9212

[startup+14.4033 s]
/proc/loadavg: 1.08 1.04 1.00 2/62 13755
/proc/meminfo: memFree=364940/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9212 CPUtime=13.09
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 759 199502 0 0 0 0 1207 102 20 0 1 0 118041352 9433088 364 18446744073709551615 4194304 5129932 140737351725424 140737351723488 140255487915102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2303 364 303 229 0 63 0
[pid=13754] ppid=13739 vsize=194436 CPUtime=0.93
/proc/13754/stat : 13754 (unclasp) R 13739 13739 1750 0 -1 4202496 53672 0 1 0 74 19 0 0 20 0 1 0 118042694 199102464 47439 18446744073709551615 4194304 6012874 140736383190368 140736383188952 4633920 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/13754/statm: 48609 47439 188 444 0 48157 0
[pid=13755] ppid=13739 vsize=22040 CPUtime=0.02
/proc/13755/stat : 13755 (parse.py) S 13739 13739 1750 0 -1 4202496 1307 0 13 0 1 1 0 0 20 0 1 0 118042694 22568960 1129 18446744073709551615 4194304 6642060 140734403825808 140734403824168 140349295773472 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/13755/statm: 5510 1129 508 598 0 596 0
Current children cumulated CPU time (s) 14.04
Current children cumulated vsize (KiB) 225688

[startup+14.8003 s]
/proc/loadavg: 1.08 1.04 1.00 2/62 13755
/proc/meminfo: memFree=364940/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9212 CPUtime=13.09
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 759 199502 0 0 0 0 1207 102 20 0 1 0 118041352 9433088 364 18446744073709551615 4194304 5129932 140737351725424 140737351723488 140255487915102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2303 364 303 229 0 63 0
[pid=13754] ppid=13739 vsize=188208 CPUtime=1.33
/proc/13754/stat : 13754 (unclasp) R 13739 13739 1750 0 -1 4202496 55221 0 1 0 113 20 0 0 20 0 1 0 118042694 192724992 46282 18446744073709551615 4194304 6012874 140736383190368 140736383189688 4499101 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/13754/statm: 47052 46282 225 444 0 46600 0
[pid=13755] ppid=13739 vsize=22188 CPUtime=0.02
/proc/13755/stat : 13755 (parse.py) S 13739 13739 1750 0 -1 4202496 1325 0 13 0 1 1 0 0 20 0 1 0 118042694 22720512 1147 18446744073709551615 4194304 6642060 140734403825808 140734403823768 140349295773472 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/13755/statm: 5547 1147 508 598 0 633 0
Current children cumulated CPU time (s) 14.44
Current children cumulated vsize (KiB) 219608

[startup+14.9013 s]
/proc/loadavg: 1.08 1.04 1.00 2/62 13755
/proc/meminfo: memFree=364940/1022884 swapFree=0/0
[pid=13739] ppid=13738 vsize=9212 CPUtime=13.09
/proc/13739/stat : 13739 (aspuncud-full) S 13738 13739 1750 0 -1 4202496 759 199502 0 0 0 0 1207 102 20 0 1 0 118041352 9433088 364 18446744073709551615 4194304 5129932 140737351725424 140737351723488 140255487915102 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13739/statm: 2303 364 303 229 0 63 0
[pid=13754] ppid=13739 vsize=188208 CPUtime=1.43
/proc/13754/stat : 13754 (unclasp) R 13739 13739 1750 0 -1 4202496 55230 0 1 0 119 24 0 0 20 0 1 0 118042694 192724992 15571 18446744073709551615 4194304 6012874 140736383190368 140736383189768 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/13754/statm: 47052 15571 234 444 0 46600 0
[pid=13755] ppid=13739 vsize=22392 CPUtime=0.02
/proc/13755/stat : 13755 (parse.py) S 13739 13739 1750 0 -1 4202496 1366 0 13 0 1 1 0 0 20 0 1 0 118042694 22929408 1188 18446744073709551615 4194304 6642060 140734403825808 140734403823976 140349295773472 0 0 16777220 20994 0 0 0 17 0 0 0 10 0 0
/proc/13755/statm: 5598 1188 508 598 0 684 0
Current children cumulated CPU time (s) 14.54
Current children cumulated vsize (KiB) 219812

Child status: 0
Real time (s): 14.9509
CPU time (s): 14.6089
CPU user time (s): 13.2888
CPU system time (s): 1.32008
CPU usage (%): 97.7128
Max. virtual memory (cumulated for all children) (KiB): 680764

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.2888
system time used= 1.32008
maximum resident set size= 547652
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 257141
page faults= 15
swaps= 0
block input operations= 69944
block output operations= 75480
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 144
involuntary context switches= 1842

runsolver used 0.024001 second user time and 0.068004 second system time

The end