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/slowlink/real/ab9005be-bacc-11e0-b0f6-00163e1e087d.cudf.log.runsolver /home/competition/aspuncud-full-1.7/aspuncud-full /home/competition/data/real/ab9005be-bacc-11e0-b0f6-00163e1e087d.cudf /tmp/misc2012/2012-09-02-22:42/full/aspuncud-full-1.7/slowlink/real/ab9005be-bacc-11e0-b0f6-00163e1e087d.cudf.result -sum(changed,installedsize),-count(removed),-notuptodate(solution),-count(changed) 

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.01 1.01 1.00 2/64 21070
/proc/meminfo: memFree=343088/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=1244 CPUtime=0
/proc/21070/stat : 21070 (aspuncud-full) R 21069 21070 1745 0 -1 4202496 115 0 0 0 0 0 0 0 20 0 1 0 120625617 1273856 39 18446744073709551615 4194304 5129932 140736666522656 140736666520248 139948696895485 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/21070/statm: 311 39 29 229 0 32 0

[startup+0.143903 s]
/proc/loadavg: 1.01 1.01 1.00 2/64 21070
/proc/meminfo: memFree=343088/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=9212 CPUtime=0.04
/proc/21070/stat : 21070 (aspuncud-full) S 21069 21070 1745 0 -1 4202496 702 2807 0 0 0 1 2 1 20 0 1 0 120625617 9433088 365 18446744073709551615 4194304 5129932 140736666522656 140736666521312 139948689486942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21070/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.200286 s]
/proc/loadavg: 1.01 1.01 1.00 2/64 21070
/proc/meminfo: memFree=343088/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=9212 CPUtime=0.04
/proc/21070/stat : 21070 (aspuncud-full) S 21069 21070 1745 0 -1 4202496 702 2807 0 0 0 1 2 1 20 0 1 0 120625617 9433088 365 18446744073709551615 4194304 5129932 140736666522656 140736666521312 139948689486942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21070/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.30031 s]
/proc/loadavg: 1.01 1.01 1.00 2/64 21070
/proc/meminfo: memFree=343088/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=9212 CPUtime=0.04
/proc/21070/stat : 21070 (aspuncud-full) S 21069 21070 1745 0 -1 4202496 702 2807 0 0 0 1 2 1 20 0 1 0 120625617 9433088 365 18446744073709551615 4194304 5129932 140736666522656 140736666521312 139948689486942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21070/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+0.700227 s]
/proc/loadavg: 1.01 1.01 1.00 2/64 21070
/proc/meminfo: memFree=343088/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=9212 CPUtime=0.04
/proc/21070/stat : 21070 (aspuncud-full) S 21069 21070 1745 0 -1 4202496 702 2807 0 0 0 1 2 1 20 0 1 0 120625617 9433088 365 18446744073709551615 4194304 5129932 140736666522656 140736666521312 139948689486942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21070/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 9212

[startup+1.50033 s]
/proc/loadavg: 1.01 1.01 1.00 2/66 21083
/proc/meminfo: memFree=306484/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=9212 CPUtime=0.04
/proc/21070/stat : 21070 (aspuncud-full) S 21069 21070 1745 0 -1 4202496 702 2807 0 0 0 1 2 1 20 0 1 0 120625617 9433088 365 18446744073709551615 4194304 5129932 140736666522656 140736666521312 139948689486942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21070/statm: 2303 365 303 229 0 63 0
[pid=21083] ppid=21070 vsize=50452 CPUtime=1.42
/proc/21083/stat : 21083 (cudf2lp) R 21070 21070 1745 0 -1 4202496 14220 0 0 0 136 6 0 0 20 0 1 0 120625620 51662848 10822 18446744073709551615 4194304 5690517 140734839251952 140734839249592 4293666 0 0 16781316 0 0 0 0 17 0 0 0 2 0 0
/proc/21083/statm: 12613 10822 160 366 0 12244 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 59664

[startup+3.10033 s]
/proc/loadavg: 1.01 1.01 1.00 2/66 21083
/proc/meminfo: memFree=276600/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=9212 CPUtime=0.04
/proc/21070/stat : 21070 (aspuncud-full) S 21069 21070 1745 0 -1 4202496 702 2807 0 0 0 1 2 1 20 0 1 0 120625617 9433088 365 18446744073709551615 4194304 5129932 140736666522656 140736666521312 139948689486942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21070/statm: 2303 365 303 229 0 63 0
[pid=21083] ppid=21070 vsize=84504 CPUtime=2.94
/proc/21083/stat : 21083 (cudf2lp) R 21070 21070 1745 0 -1 4202496 27254 0 0 0 282 12 0 0 20 0 1 0 120625620 86532096 20854 18446744073709551615 4194304 5690517 140734839251952 140734839249304 4306124 0 0 16781316 0 0 0 0 17 0 0 0 9 0 0
/proc/21083/statm: 21126 20854 174 366 0 20757 0
Current children cumulated CPU time (s) 2.98
Current children cumulated vsize (KiB) 93716

[startup+6.30031 s]
/proc/loadavg: 1.00 1.01 1.00 2/66 21084
/proc/meminfo: memFree=217700/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=9212 CPUtime=3.29
/proc/21070/stat : 21070 (aspuncud-full) S 21069 21070 1745 0 -1 4202496 730 30063 0 0 0 1 312 16 20 0 1 0 120625617 9433088 365 18446744073709551615 4194304 5129932 140736666522656 140736666521312 139948689486942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21070/statm: 2303 365 303 229 0 63 0
[pid=21084] ppid=21070 vsize=153248 CPUtime=2.86
/proc/21084/stat : 21084 (gringo) R 21070 21070 1745 0 -1 4202496 36810 0 0 0 270 16 0 0 20 0 1 0 120625957 156925952 32141 18446744073709551615 4194304 6531320 140736971668016 140736971664632 5520829 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21084/statm: 38312 32141 282 571 0 37733 0
Current children cumulated CPU time (s) 6.15
Current children cumulated vsize (KiB) 162460

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

[startup+6.4004 s]
/proc/loadavg: 1.00 1.01 1.00 2/66 21084
/proc/meminfo: memFree=217700/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=9212 CPUtime=3.29
/proc/21070/stat : 21070 (aspuncud-full) S 21069 21070 1745 0 -1 4202496 730 30063 0 0 0 1 312 16 20 0 1 0 120625617 9433088 365 18446744073709551615 4194304 5129932 140736666522656 140736666521312 139948689486942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21070/statm: 2303 365 303 229 0 63 0
[pid=21084] ppid=21070 vsize=153248 CPUtime=2.96
/proc/21084/stat : 21084 (gringo) R 21070 21070 1745 0 -1 4202496 37042 0 0 0 279 17 0 0 20 0 1 0 120625957 156925952 32373 18446744073709551615 4194304 6531320 140736971668016 140736971665000 4356546 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21084/statm: 38312 32373 282 571 0 37733 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 162460

[startup+8.00026 s]
/proc/loadavg: 1.00 1.01 1.00 2/66 21084
/proc/meminfo: memFree=48068/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=9212 CPUtime=3.29
/proc/21070/stat : 21070 (aspuncud-full) S 21069 21070 1745 0 -1 4202496 730 30063 0 0 0 1 312 16 20 0 1 0 120625617 9433088 365 18446744073709551615 4194304 5129932 140736666522656 140736666521312 139948689486942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21070/statm: 2303 365 303 229 0 63 0
[pid=21084] ppid=21070 vsize=353304 CPUtime=4.55
/proc/21084/stat : 21084 (gringo) R 21070 21070 1745 0 -1 4202496 82049 0 0 0 424 31 0 0 20 0 1 0 120625957 361783296 73283 18446744073709551615 4194304 6531320 140736971668016 140736971664632 4593181 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21084/statm: 88326 73283 283 571 0 87747 0
Current children cumulated CPU time (s) 7.84
Current children cumulated vsize (KiB) 362516

[startup+8.80029 s]
/proc/loadavg: 1.00 1.01 1.00 2/66 21084
/proc/meminfo: memFree=10092/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=9212 CPUtime=3.29
/proc/21070/stat : 21070 (aspuncud-full) S 21069 21070 1745 0 -1 4202496 730 30063 0 0 0 1 312 16 20 0 1 0 120625617 9433088 365 18446744073709551615 4194304 5129932 140736666522656 140736666521312 139948689486942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21070/statm: 2303 365 303 229 0 63 0
[pid=21084] ppid=21070 vsize=413428 CPUtime=5.25
/proc/21084/stat : 21084 (gringo) R 21070 21070 1745 0 -1 4202496 95125 0 0 0 488 37 0 0 20 0 1 0 120625957 423350272 86359 18446744073709551615 4194304 6531320 140736971668016 140736971664824 5507417 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/21084/statm: 103357 86359 284 571 0 102778 0
Current children cumulated CPU time (s) 8.54
Current children cumulated vsize (KiB) 422640

[startup+9.60021 s]
/proc/loadavg: 1.00 1.01 1.00 2/66 21084
/proc/meminfo: memFree=10092/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=9212 CPUtime=8.84
/proc/21070/stat : 21070 (aspuncud-full) S 21069 21070 1745 0 -1 4202496 769 125192 0 0 0 1 821 62 20 0 1 0 120625617 9433088 365 18446744073709551615 4194304 5129932 140736666522656 140736666520720 139948689486942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21070/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 8.84
Current children cumulated vsize (KiB) 9212

[startup+10.0038 s]
/proc/loadavg: 1.00 1.01 1.00 2/67 21086
/proc/meminfo: memFree=234812/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=9212 CPUtime=9.73
/proc/21070/stat : 21070 (aspuncud-full) D 21069 21070 1745 0 -1 4202496 785 161947 0 13 0 1 896 76 20 0 1 0 120625617 9433088 365 18446744073709551615 4194304 5129932 140736666522656 140736666519992 139948689629301 0 0 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/21070/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 9.73
Current children cumulated vsize (KiB) 9212

[startup+10.1003 s]
/proc/loadavg: 1.00 1.01 1.00 2/67 21086
/proc/meminfo: memFree=234812/1022884 swapFree=0/0
[pid=21070] ppid=21069 vsize=9212 CPUtime=9.73
/proc/21070/stat : 21070 (aspuncud-full) S 21069 21070 1745 0 -1 4202496 804 161947 0 13 0 1 896 76 20 0 1 0 120625617 9433088 365 18446744073709551615 4194304 5129932 140736666522656 140736666520208 139948689486942 0 65536 16781316 1115778811 0 0 0 17 0 0 0 2 0 0
/proc/21070/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 9.73
Current children cumulated vsize (KiB) 9212

Child status: 0
Real time (s): 10.1188
CPU time (s): 9.75261
CPU user time (s): 8.97256
CPU system time (s): 0.780048
CPU usage (%): 96.381
Max. virtual memory (cumulated for all children) (KiB): 422640

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 8.97256
system time used= 0.780048
maximum resident set size= 345436
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 162984
page faults= 14
swaps= 0
block input operations= 44848
block output operations= 42736
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 375
involuntary context switches= 1281

runsolver used 0 second user time and 0.072004 second system time

The end