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/upgrade/upgrade/difficult/rand491.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/upgrade/difficult/rand491.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/upgrade/upgrade/difficult/rand491.cudf.result -count(down),-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.16 1.05 0.73 2/57 15615
/proc/meminfo: memFree=366936/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=3152 CPUtime=0
/proc/15615/stat : 15615 (runsolver) R 15614 32685 32685 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 38924939 3227648 32 18446744073709551615 134512640 134586868 4289850064 4289848112 4151800880 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/15615/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.203094 s]
/proc/loadavg: 1.16 1.05 0.73 2/57 15615
/proc/meminfo: memFree=366936/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=0.04
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 699 2805 2 5 0 0 2 2 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151968 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.300328 s]
/proc/loadavg: 1.16 1.05 0.73 2/57 15615
/proc/meminfo: memFree=366936/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=0.04
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 699 2805 2 5 0 0 2 2 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151968 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.400311 s]
/proc/loadavg: 1.16 1.05 0.73 2/57 15615
/proc/meminfo: memFree=366936/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=0.04
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 699 2805 2 5 0 0 2 2 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151968 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.70022 s]
/proc/loadavg: 1.16 1.05 0.73 2/57 15615
/proc/meminfo: memFree=366936/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=0.04
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 699 2805 2 5 0 0 2 2 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151968 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.5003 s]
/proc/loadavg: 1.16 1.05 0.73 2/59 15628
/proc/meminfo: memFree=330456/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=0.04
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 699 2805 2 5 0 0 2 2 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151968 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
[pid=15628] ppid=15615 vsize=31912 CPUtime=1.3
/proc/15628/stat : 15628 (cudf2lp) R 15615 15615 32685 0 -1 4202496 9391 0 1 0 126 4 0 0 20 0 1 0 38924947 32677888 7658 18446744073709551615 4194304 5690517 140737307665424 140737307663064 4381976 0 0 16781316 0 0 0 0 17 0 0 0 10 0 0
/proc/15628/statm: 7978 7658 160 366 0 7609 0
Current children cumulated CPU time (s) 1.34
Current children cumulated vsize (KiB) 41124

[startup+3.10032 s]
/proc/loadavg: 1.14 1.05 0.73 2/59 15628
/proc/meminfo: memFree=296356/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=0.04
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 699 2805 2 5 0 0 2 2 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151968 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
[pid=15628] ppid=15615 vsize=99148 CPUtime=2.76
/proc/15628/stat : 15628 (cudf2lp) R 15615 15615 32685 0 -1 4202496 28079 0 1 0 263 13 0 0 20 0 1 0 38924947 101527552 21352 18446744073709551615 4194304 5690517 140737307665424 140737307663064 4683257 0 0 16781316 0 0 0 0 17 0 0 0 23 0 0
/proc/15628/statm: 24787 21352 160 366 0 24418 0
Current children cumulated CPU time (s) 2.8
Current children cumulated vsize (KiB) 108360

[startup+6.30031 s]
/proc/loadavg: 1.14 1.05 0.73 2/59 15629
/proc/meminfo: memFree=307268/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=5
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 727 44083 2 6 0 0 470 30 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151968 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
[pid=15629] ppid=15615 vsize=28744 CPUtime=0.95
/proc/15629/stat : 15629 (gringo) R 15615 15615 32685 0 -1 4202496 7978 0 1 0 89 6 0 0 20 0 1 0 38925470 29433856 5871 18446744073709551615 4194304 6531320 140735857752736 140735857749352 5520799 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/15629/statm: 7186 5871 259 571 0 6607 0
Current children cumulated CPU time (s) 5.95
Current children cumulated vsize (KiB) 37956

[startup+12.7003 s]
/proc/loadavg: 1.12 1.05 0.74 3/59 15629
/proc/meminfo: memFree=9280/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=5
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 727 44083 2 6 0 0 470 30 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151968 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
[pid=15629] ppid=15615 vsize=394916 CPUtime=7.22
/proc/15629/stat : 15629 (gringo) R 15615 15615 32685 0 -1 4202496 94437 0 1 0 678 44 0 0 20 0 1 0 38925470 404393984 84134 18446744073709551615 4194304 6531320 140735857752736 140735857749352 5512376 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/15629/statm: 98729 84134 282 571 0 98150 0
Current children cumulated CPU time (s) 12.22
Current children cumulated vsize (KiB) 404128

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

[startup+12.9004 s]
/proc/loadavg: 1.12 1.05 0.74 3/59 15629
/proc/meminfo: memFree=9280/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=5
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 727 44083 2 6 0 0 470 30 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151968 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
[pid=15629] ppid=15615 vsize=436368 CPUtime=7.37
/proc/15629/stat : 15629 (gringo) R 15615 15615 32685 0 -1 4202496 104682 0 1 0 689 48 0 0 20 0 1 0 38925470 446840832 86186 18446744073709551615 4194304 6531320 140735857752736 140735857749352 4443008 0 0 16781316 16386 0 0 0 17 0 0 0 1 0 0
/proc/15629/statm: 109092 86186 282 571 0 108513 0
Current children cumulated CPU time (s) 12.37
Current children cumulated vsize (KiB) 445580

[startup+16.1002 s]
/proc/loadavg: 1.12 1.05 0.74 2/59 15629
/proc/meminfo: memFree=50176/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=15.22
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 767 182937 2 7 0 0 1415 107 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151376 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 15.22
Current children cumulated vsize (KiB) 9212

[startup+16.9004 s]
/proc/loadavg: 1.12 1.05 0.74 2/60 15631
/proc/meminfo: memFree=349020/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=15.22
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 767 182937 2 7 0 0 1415 107 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151376 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
[pid=15630] ppid=15615 vsize=168928 CPUtime=1.01
/proc/15630/stat : 15630 (unclasp) R 15615 15615 32685 0 -1 4202496 46877 0 0 0 85 16 0 0 20 0 1 0 38926524 172982272 40643 18446744073709551615 4194304 6012874 140734516461888 140734516460648 4633360 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15630/statm: 42232 40643 186 444 0 41780 0
[pid=15631] ppid=15615 vsize=22040 CPUtime=0.01
/proc/15631/stat : 15631 (parse.py) S 15615 15615 32685 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 38926524 22568960 1128 18446744073709551615 4194304 6642060 140736011996720 140736011995080 139719983400736 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15631/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 16.24
Current children cumulated vsize (KiB) 200180

[startup+17.3004 s]
/proc/loadavg: 1.12 1.05 0.74 2/60 15631
/proc/meminfo: memFree=349020/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=15.22
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 767 182937 2 7 0 0 1415 107 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151376 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
[pid=15630] ppid=15615 vsize=175452 CPUtime=1.41
/proc/15630/stat : 15630 (unclasp) R 15615 15615 32685 0 -1 4202496 48520 0 0 0 124 17 0 0 20 0 1 0 38926524 179662848 42286 18446744073709551615 4194304 6012874 140734516461888 140734516461208 4548536 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15630/statm: 43863 42286 220 444 0 43411 0
[pid=15631] ppid=15615 vsize=22040 CPUtime=0.01
/proc/15631/stat : 15631 (parse.py) S 15615 15615 32685 0 -1 4202496 1319 0 0 0 0 1 0 0 20 0 1 0 38926524 22568960 1128 18446744073709551615 4194304 6642060 140736011996720 140736011995080 139719983400736 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15631/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 16.64
Current children cumulated vsize (KiB) 206704

[startup+17.7004 s]
/proc/loadavg: 1.11 1.05 0.74 2/60 15631
/proc/meminfo: memFree=328436/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=15.22
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 767 182937 2 7 0 0 1415 107 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151376 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
[pid=15630] ppid=15615 vsize=163148 CPUtime=1.81
/proc/15630/stat : 15630 (unclasp) R 15615 15615 32685 0 -1 4202496 48547 0 0 0 163 18 0 0 20 0 1 0 38926524 167063552 39975 18446744073709551615 4194304 6012874 140734516461888 140734516461208 4548792 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15630/statm: 40787 39975 225 444 0 40335 0
[pid=15631] ppid=15615 vsize=22336 CPUtime=0.01
/proc/15631/stat : 15631 (parse.py) S 15615 15615 32685 0 -1 4202496 1391 0 0 0 0 1 0 0 20 0 1 0 38926524 22872064 1200 18446744073709551615 4194304 6642060 140736011996720 140736011994920 139719983400736 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15631/statm: 5584 1200 508 598 0 670 0
Current children cumulated CPU time (s) 17.04
Current children cumulated vsize (KiB) 194696

[startup+17.8053 s]
/proc/loadavg: 1.11 1.05 0.74 2/60 15631
/proc/meminfo: memFree=328436/1022884 swapFree=0/0
[pid=15615] ppid=15614 vsize=9212 CPUtime=15.22
/proc/15615/stat : 15615 (aspuncud-full) S 15614 15615 32685 0 -1 4202496 767 182937 2 7 0 0 1415 107 20 0 1 0 38924939 9433088 365 18446744073709551615 4194304 5129932 140735728153312 140735728151376 140433621099614 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/15615/statm: 2303 365 303 229 0 63 0
[pid=15630] ppid=15615 vsize=163148 CPUtime=1.91
/proc/15630/stat : 15630 (unclasp) R 15615 15615 32685 0 -1 4202496 48556 0 0 0 170 21 0 0 20 0 1 0 38926524 167063552 13360 18446744073709551615 4194304 6012874 140734516461888 140734516461288 5474154 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/15630/statm: 40787 13360 234 444 0 40335 0
[pid=15631] ppid=15615 vsize=22336 CPUtime=0.01
/proc/15631/stat : 15631 (parse.py) S 15615 15615 32685 0 -1 4202496 1391 0 0 0 0 1 0 0 20 0 1 0 38926524 22872064 1200 18446744073709551615 4194304 6642060 140736011996720 140736011994920 139719983400736 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/15631/statm: 5584 1200 508 598 0 670 0
Current children cumulated CPU time (s) 17.14
Current children cumulated vsize (KiB) 194696

Child status: 0
Real time (s): 17.8444
CPU time (s): 17.2251
CPU user time (s): 15.873
CPU system time (s): 1.35208
CPU usage (%): 96.5292
Max. virtual memory (cumulated for all children) (KiB): 599836

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 15.873
system time used= 1.35208
maximum resident set size= 481416
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 233938
page faults= 9
swaps= 0
block input operations= 69080
block output operations= 66984
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 164
involuntary context switches= 528

runsolver used 0.028001 second user time and 0.092005 second system time

The end