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/real/3e4f8550-0b33-11df-942d-00163e1d94dc.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/3e4f8550-0b33-11df-942d-00163e1d94dc.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/dist-upgrade/real/3e4f8550-0b33-11df-942d-00163e1d94dc.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.06 1.02 2/59 13168
/proc/meminfo: memFree=513512/1022884 swapFree=0/0
[pid=13168] ppid=13167 vsize=3152 CPUtime=0
/proc/13168/stat : 13168 (runsolver) R 13167 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 118012387 3227648 32 18446744073709551615 134512640 134586868 4287875200 4287873248 4151297072 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/13168/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.110037 s]
/proc/loadavg: 1.02 1.06 1.02 2/59 13168
/proc/meminfo: memFree=513512/1022884 swapFree=0/0
[pid=13168] ppid=13167 vsize=9212 CPUtime=0.03
/proc/13168/stat : 13168 (aspuncud-full) S 13167 13168 1750 0 -1 4202496 695 2811 0 0 0 0 1 2 20 0 1 0 118012387 9433088 364 18446744073709551615 4194304 5129932 140735493057536 140735493056192 140528738305118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13168/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.200331 s]
/proc/loadavg: 1.02 1.06 1.02 2/59 13168
/proc/meminfo: memFree=513512/1022884 swapFree=0/0
[pid=13168] ppid=13167 vsize=9212 CPUtime=0.03
/proc/13168/stat : 13168 (aspuncud-full) S 13167 13168 1750 0 -1 4202496 695 2811 0 0 0 0 1 2 20 0 1 0 118012387 9433088 364 18446744073709551615 4194304 5129932 140735493057536 140735493056192 140528738305118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13168/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300327 s]
/proc/loadavg: 1.02 1.06 1.02 2/59 13168
/proc/meminfo: memFree=513512/1022884 swapFree=0/0
[pid=13168] ppid=13167 vsize=9212 CPUtime=0.03
/proc/13168/stat : 13168 (aspuncud-full) S 13167 13168 1750 0 -1 4202496 695 2811 0 0 0 0 1 2 20 0 1 0 118012387 9433088 364 18446744073709551615 4194304 5129932 140735493057536 140735493056192 140528738305118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13168/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.70024 s]
/proc/loadavg: 1.02 1.06 1.02 2/59 13168
/proc/meminfo: memFree=513512/1022884 swapFree=0/0
[pid=13168] ppid=13167 vsize=9212 CPUtime=0.03
/proc/13168/stat : 13168 (aspuncud-full) S 13167 13168 1750 0 -1 4202496 695 2811 0 0 0 0 1 2 20 0 1 0 118012387 9433088 364 18446744073709551615 4194304 5129932 140735493057536 140735493056192 140528738305118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13168/statm: 2303 364 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.02 1.06 1.02 2/61 13181
/proc/meminfo: memFree=476164/1022884 swapFree=0/0
[pid=13168] ppid=13167 vsize=9212 CPUtime=0.03
/proc/13168/stat : 13168 (aspuncud-full) S 13167 13168 1750 0 -1 4202496 695 2811 0 0 0 0 1 2 20 0 1 0 118012387 9433088 364 18446744073709551615 4194304 5129932 140735493057536 140735493056192 140528738305118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13168/statm: 2303 364 303 229 0 63 0
[pid=13181] ppid=13168 vsize=52524 CPUtime=1.42
/proc/13181/stat : 13181 (cudf2lp) R 13168 13168 1750 0 -1 4202496 14820 0 0 0 134 8 0 0 20 0 1 0 118012390 53784576 11422 18446744073709551615 4194304 5690517 140733498631472 140733498629112 4970403 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/13181/statm: 13131 11422 160 366 0 12762 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 61736

[startup+3.10028 s]
/proc/loadavg: 1.02 1.06 1.02 2/61 13181
/proc/meminfo: memFree=437600/1022884 swapFree=0/0
[pid=13168] ppid=13167 vsize=9212 CPUtime=0.03
/proc/13168/stat : 13168 (aspuncud-full) S 13167 13168 1750 0 -1 4202496 695 2811 0 0 0 0 1 2 20 0 1 0 118012387 9433088 364 18446744073709551615 4194304 5129932 140735493057536 140735493056192 140528738305118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13168/statm: 2303 364 303 229 0 63 0
[pid=13181] ppid=13168 vsize=98748 CPUtime=2.97
/proc/13181/stat : 13181 (cudf2lp) R 13168 13168 1750 0 -1 4202496 34448 0 0 0 281 16 0 0 20 0 1 0 118012390 101117952 24321 18446744073709551615 4194304 5690517 140733498631472 140733498628808 4956281 0 0 16781316 0 0 0 0 17 0 0 0 7 0 0
/proc/13181/statm: 24687 24321 174 366 0 24318 0
Current children cumulated CPU time (s) 3
Current children cumulated vsize (KiB) 107960

[startup+6.30028 s]
/proc/loadavg: 1.02 1.06 1.02 2/61 13182
/proc/meminfo: memFree=330588/1022884 swapFree=0/0
[pid=13168] ppid=13167 vsize=9212 CPUtime=3.1
/proc/13168/stat : 13168 (aspuncud-full) S 13167 13168 1750 0 -1 4202496 722 37261 0 0 0 0 289 21 20 0 1 0 118012387 9433088 364 18446744073709551615 4194304 5129932 140735493057536 140735493056192 140528738305118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13168/statm: 2303 364 303 229 0 63 0
[pid=13182] ppid=13168 vsize=255576 CPUtime=3.05
/proc/13182/stat : 13182 (gringo) R 13168 13168 1750 0 -1 4202496 62802 0 0 0 286 19 0 0 20 0 1 0 118012706 261709824 53556 18446744073709551615 4194304 6531320 140734354884752 140734354881736 5632288 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/13182/statm: 63894 53556 283 571 0 63315 0
Current children cumulated CPU time (s) 6.15
Current children cumulated vsize (KiB) 264788

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

[startup+6.40032 s]
/proc/loadavg: 1.02 1.06 1.02 2/61 13182
/proc/meminfo: memFree=330588/1022884 swapFree=0/0
[pid=13168] ppid=13167 vsize=9212 CPUtime=3.1
/proc/13168/stat : 13168 (aspuncud-full) S 13167 13168 1750 0 -1 4202496 722 37261 0 0 0 0 289 21 20 0 1 0 118012387 9433088 364 18446744073709551615 4194304 5129932 140735493057536 140735493056192 140528738305118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13168/statm: 2303 364 303 229 0 63 0
[pid=13182] ppid=13168 vsize=268156 CPUtime=3.15
/proc/13182/stat : 13182 (gringo) R 13168 13168 1750 0 -1 4202496 65754 0 0 0 295 20 0 0 20 0 1 0 118012706 274591744 56508 18446744073709551615 4194304 6531320 140734354884752 140734354881368 4641249 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/13182/statm: 67039 56508 283 571 0 66460 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 277368

[startup+8.00067 s]
/proc/loadavg: 1.02 1.06 1.02 2/61 13182
/proc/meminfo: memFree=101808/1022884 swapFree=0/0
[pid=13168] ppid=13167 vsize=9212 CPUtime=3.1
/proc/13168/stat : 13168 (aspuncud-full) S 13167 13168 1750 0 -1 4202496 722 37261 0 0 0 0 289 21 20 0 1 0 118012387 9433088 364 18446744073709551615 4194304 5129932 140735493057536 140735493056192 140528738305118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13168/statm: 2303 364 303 229 0 63 0
[pid=13182] ppid=13168 vsize=391076 CPUtime=4.74
/proc/13182/stat : 13182 (gringo) R 13168 13168 1750 0 -1 4202496 100497 0 0 0 442 32 0 0 20 0 1 0 118012706 400461824 74357 18446744073709551615 4194304 6531320 140734354884752 140734354882440 5808234 0 0 16781316 16386 0 0 0 17 0 0 0 2 0 0
/proc/13182/statm: 97769 74357 284 571 0 97190 0
Current children cumulated CPU time (s) 7.84
Current children cumulated vsize (KiB) 400288

[startup+8.40021 s]
/proc/loadavg: 1.02 1.06 1.02 2/61 13182
/proc/meminfo: memFree=101808/1022884 swapFree=0/0
[pid=13168] ppid=13167 vsize=9212 CPUtime=7.92
/proc/13168/stat : 13168 (aspuncud-full) S 13167 13168 1750 0 -1 4202496 761 137762 0 0 0 1 731 60 20 0 1 0 118012387 9433088 364 18446744073709551615 4194304 5129932 140735493057536 140735493055600 140528738305118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13168/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 7.92
Current children cumulated vsize (KiB) 9212

[startup+8.80021 s]
/proc/loadavg: 1.02 1.06 1.02 2/62 13184
/proc/meminfo: memFree=346204/1022884 swapFree=0/0
[pid=13168] ppid=13167 vsize=9212 CPUtime=7.92
/proc/13168/stat : 13168 (aspuncud-full) S 13167 13168 1750 0 -1 4202496 761 137762 0 0 0 1 731 60 20 0 1 0 118012387 9433088 364 18446744073709551615 4194304 5129932 140735493057536 140735493055600 140528738305118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13168/statm: 2303 364 303 229 0 63 0
[pid=13183] ppid=13168 vsize=119788 CPUtime=0.7
/proc/13183/stat : 13183 (unclasp) R 13168 13168 1750 0 -1 4202496 35386 0 0 0 59 11 0 0 20 0 1 0 118013194 122662912 29456 18446744073709551615 4194304 6012874 140735100404896 140735100404072 5251022 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13183/statm: 29947 29456 225 444 0 29495 0
[pid=13184] ppid=13168 vsize=22188 CPUtime=0
/proc/13184/stat : 13184 (parse.py) S 13168 13168 1750 0 -1 4202496 1329 0 0 0 0 0 0 0 20 0 1 0 118013194 22720512 1139 18446744073709551615 4194304 6642060 140737296352528 140737296350568 139712881948448 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13184/statm: 5547 1139 508 598 0 633 0
Current children cumulated CPU time (s) 8.62
Current children cumulated vsize (KiB) 151188

[startup+8.90338 s]
/proc/loadavg: 1.02 1.06 1.02 2/62 13184
/proc/meminfo: memFree=346204/1022884 swapFree=0/0
[pid=13168] ppid=13167 vsize=9212 CPUtime=7.92
/proc/13168/stat : 13168 (aspuncud-full) S 13167 13168 1750 0 -1 4202496 761 137762 0 0 0 1 731 60 20 0 1 0 118012387 9433088 364 18446744073709551615 4194304 5129932 140735493057536 140735493055600 140528738305118 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/13168/statm: 2303 364 303 229 0 63 0
[pid=13183] ppid=13168 vsize=119788 CPUtime=0.8
/proc/13183/stat : 13183 (unclasp) R 13168 13168 1750 0 -1 4202496 35387 0 0 0 69 11 0 0 20 0 1 0 118013194 122662912 29457 18446744073709551615 4194304 6012874 140735100404896 140735100404216 4855815 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/13183/statm: 29947 29457 226 444 0 29495 0
[pid=13184] ppid=13168 vsize=22188 CPUtime=0
/proc/13184/stat : 13184 (parse.py) S 13168 13168 1750 0 -1 4202496 1357 0 0 0 0 0 0 0 20 0 1 0 118013194 22720512 1167 18446744073709551615 4194304 6642060 140737296352528 140737296350648 139712881948448 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/13184/statm: 5547 1167 508 598 0 633 0
Current children cumulated CPU time (s) 8.72
Current children cumulated vsize (KiB) 151188

Child status: 0
Real time (s): 8.97291
CPU time (s): 8.82855
CPU user time (s): 8.0405
CPU system time (s): 0.788049
CPU usage (%): 98.3911
Max. virtual memory (cumulated for all children) (KiB): 437160

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 8.0405
system time used= 0.788049
maximum resident set size= 365004
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 175562
page faults= 0
swaps= 0
block input operations= 44272
block output operations= 48768
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 99
involuntary context switches= 1438

runsolver used 0.004 second user time and 0.048003 second system time

The end