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 150 -d 10 -w /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/install/rand937.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/install/rand937.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/install/rand937.cudf.result -sum(solution,installedsize),-count(removed) 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 150 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 180 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: 0.93 0.98 0.98 2/56 9316
/proc/meminfo: memFree=377900/1022884 swapFree=0/0
[pid=9316] ppid=9315 vsize=9204 CPUtime=0
/proc/9316/stat : 9316 (aspcud-basic) S 9315 9316 32685 0 -1 4202496 432 0 0 0 0 0 0 0 20 0 1 0 37507442 9424896 332 18446744073709551615 4194304 5129932 140736100914528 140736100911992 140122625341216 0 0 16781316 65536 0 0 0 17 0 0 0 0 0 0
/proc/9316/statm: 2301 332 272 229 0 61 0

[startup+0.112569 s]
/proc/loadavg: 0.93 0.98 0.98 2/56 9316
/proc/meminfo: memFree=377900/1022884 swapFree=0/0
[pid=9316] ppid=9315 vsize=9212 CPUtime=0.02
/proc/9316/stat : 9316 (aspcud-basic) S 9315 9316 32685 0 -1 4202496 738 3609 0 0 0 0 2 0 20 0 1 0 37507442 9433088 365 18446744073709551615 4194304 5129932 140736100914528 140736100913184 140122625197150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9316/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.200275 s]
/proc/loadavg: 0.93 0.98 0.98 2/56 9316
/proc/meminfo: memFree=377900/1022884 swapFree=0/0
[pid=9316] ppid=9315 vsize=9212 CPUtime=0.02
/proc/9316/stat : 9316 (aspcud-basic) S 9315 9316 32685 0 -1 4202496 738 3609 0 0 0 0 2 0 20 0 1 0 37507442 9433088 365 18446744073709551615 4194304 5129932 140736100914528 140736100913184 140122625197150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9316/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.300255 s]
/proc/loadavg: 0.93 0.98 0.98 2/56 9316
/proc/meminfo: memFree=377900/1022884 swapFree=0/0
[pid=9316] ppid=9315 vsize=9212 CPUtime=0.02
/proc/9316/stat : 9316 (aspcud-basic) S 9315 9316 32685 0 -1 4202496 738 3609 0 0 0 0 2 0 20 0 1 0 37507442 9433088 365 18446744073709551615 4194304 5129932 140736100914528 140736100913184 140122625197150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9316/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+0.700197 s]
/proc/loadavg: 0.93 0.98 0.98 2/56 9316
/proc/meminfo: memFree=377900/1022884 swapFree=0/0
[pid=9316] ppid=9315 vsize=9212 CPUtime=0.02
/proc/9316/stat : 9316 (aspcud-basic) S 9315 9316 32685 0 -1 4202496 738 3609 0 0 0 0 2 0 20 0 1 0 37507442 9433088 365 18446744073709551615 4194304 5129932 140736100914528 140736100913184 140122625197150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9316/statm: 2303 365 303 229 0 63 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 9212

[startup+1.50026 s]
/proc/loadavg: 0.94 0.98 0.98 2/58 9332
/proc/meminfo: memFree=334336/1022884 swapFree=0/0
[pid=9316] ppid=9315 vsize=9212 CPUtime=0.02
/proc/9316/stat : 9316 (aspcud-basic) S 9315 9316 32685 0 -1 4202496 738 3609 0 0 0 0 2 0 20 0 1 0 37507442 9433088 365 18446744073709551615 4194304 5129932 140736100914528 140736100913184 140122625197150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9316/statm: 2303 365 303 229 0 63 0
[pid=9332] ppid=9316 vsize=50676 CPUtime=1.47
/proc/9332/stat : 9332 (cudf2lp) R 9316 9316 32685 0 -1 4202496 15210 0 0 0 142 5 0 0 20 0 1 0 37507445 51892224 11811 18446744073709551615 4194304 5690517 140736226685552 140736226683192 4360825 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/9332/statm: 12669 11811 160 366 0 12300 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 59888

[startup+3.10028 s]
/proc/loadavg: 0.94 0.98 0.98 2/58 9332
/proc/meminfo: memFree=297136/1022884 swapFree=0/0
[pid=9316] ppid=9315 vsize=9212 CPUtime=0.02
/proc/9316/stat : 9316 (aspcud-basic) S 9315 9316 32685 0 -1 4202496 738 3609 0 0 0 0 2 0 20 0 1 0 37507442 9433088 365 18446744073709551615 4194304 5129932 140736100914528 140736100913184 140122625197150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9316/statm: 2303 365 303 229 0 63 0
[pid=9332] ppid=9316 vsize=114764 CPUtime=3.05
/proc/9332/stat : 9332 (cudf2lp) R 9316 9316 32685 0 -1 4202496 39320 0 0 0 290 15 0 0 20 0 1 0 37507445 117518336 28363 18446744073709551615 4194304 5690517 140736226685552 140736226682552 4956281 0 0 16781316 0 0 0 0 17 0 0 0 0 0 0
/proc/9332/statm: 28691 28363 174 366 0 28322 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 123976

[startup+6.30026 s]
/proc/loadavg: 0.94 0.98 0.98 2/58 9333
/proc/meminfo: memFree=211328/1022884 swapFree=0/0
[pid=9316] ppid=9315 vsize=9212 CPUtime=3.22
/proc/9316/stat : 9316 (aspcud-basic) S 9315 9316 32685 0 -1 4202496 764 42931 0 0 0 0 304 18 20 0 1 0 37507442 9433088 365 18446744073709551615 4194304 5129932 140736100914528 140736100913184 140122625197150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9316/statm: 2303 365 303 229 0 63 0
[pid=9333] ppid=9316 vsize=285984 CPUtime=3.04
/proc/9333/stat : 9333 (gringo) R 9316 9316 32685 0 -1 4202496 69687 0 0 0 285 19 0 0 20 0 1 0 37507765 292847616 60407 18446744073709551615 4194304 6531320 140734548118096 140734548115080 5511045 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/9333/statm: 71496 60407 283 571 0 70917 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 295196

[startup+12.7003 s]
/proc/loadavg: 1.03 1.00 0.99 2/59 9335
/proc/meminfo: memFree=235128/1022884 swapFree=0/0
[pid=9316] ppid=9315 vsize=9212 CPUtime=7.63
/proc/9316/stat : 9316 (aspcud-basic) S 9315 9316 32685 0 -1 4202496 804 140419 0 0 0 0 710 53 20 0 1 0 37507442 9433088 365 18446744073709551615 4194304 5129932 140736100914528 140736100912592 140122625197150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9316/statm: 2303 365 303 229 0 63 0
[pid=9334] ppid=9316 vsize=126348 CPUtime=4.96
/proc/9334/stat : 9334 (clasp) R 9316 9316 32685 0 -1 4202496 36986 0 0 0 488 8 0 0 20 0 1 0 37508211 129380352 31084 18446744073709551615 4194304 6238623 140735420735584 140735420732608 4353190 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9334/statm: 31587 31084 263 500 0 31084 0
[pid=9335] ppid=9316 vsize=22040 CPUtime=0.01
/proc/9335/stat : 9335 (parse.py) S 9316 9316 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37508211 22568960 1128 18446744073709551615 4194304 6642060 140734466904608 140734466902968 140622143244064 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9335/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.6
Current children cumulated vsize (KiB) 157600

[startup+25.5003 s]
/proc/loadavg: 1.02 1.00 0.99 2/59 9335
/proc/meminfo: memFree=235252/1022884 swapFree=0/0
[pid=9316] ppid=9315 vsize=9212 CPUtime=7.63
/proc/9316/stat : 9316 (aspcud-basic) S 9315 9316 32685 0 -1 4202496 804 140419 0 0 0 0 710 53 20 0 1 0 37507442 9433088 365 18446744073709551615 4194304 5129932 140736100914528 140736100912592 140122625197150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9316/statm: 2303 365 303 229 0 63 0
[pid=9334] ppid=9316 vsize=126348 CPUtime=17.69
/proc/9334/stat : 9334 (clasp) R 9316 9316 32685 0 -1 4202496 36986 0 0 0 1761 8 0 0 20 0 1 0 37508211 129380352 31084 18446744073709551615 4194304 6238623 140735420735584 140735420732608 4409898 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9334/statm: 31587 31084 263 500 0 31084 0
[pid=9335] ppid=9316 vsize=22040 CPUtime=0.01
/proc/9335/stat : 9335 (parse.py) S 9316 9316 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37508211 22568960 1128 18446744073709551615 4194304 6642060 140734466904608 140734466902968 140622143244064 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9335/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.33
Current children cumulated vsize (KiB) 157600

[startup+51.1004 s]
/proc/loadavg: 1.01 1.00 0.99 2/59 9335
/proc/meminfo: memFree=235252/1022884 swapFree=0/0
[pid=9316] ppid=9315 vsize=9212 CPUtime=7.63
/proc/9316/stat : 9316 (aspcud-basic) S 9315 9316 32685 0 -1 4202496 804 140419 0 0 0 0 710 53 20 0 1 0 37507442 9433088 365 18446744073709551615 4194304 5129932 140736100914528 140736100912592 140122625197150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9316/statm: 2303 365 303 229 0 63 0
[pid=9334] ppid=9316 vsize=126348 CPUtime=43.15
/proc/9334/stat : 9334 (clasp) R 9316 9316 32685 0 -1 4202496 36986 0 0 0 4307 8 0 0 20 0 1 0 37508211 129380352 31084 18446744073709551615 4194304 6238623 140735420735584 140735420732608 4677225 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9334/statm: 31587 31084 263 500 0 31084 0
[pid=9335] ppid=9316 vsize=22040 CPUtime=0.01
/proc/9335/stat : 9335 (parse.py) S 9316 9316 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37508211 22568960 1128 18446744073709551615 4194304 6642060 140734466904608 140734466902968 140622143244064 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9335/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.79
Current children cumulated vsize (KiB) 157600

[startup+102.3 s]
/proc/loadavg: 1.00 1.00 0.99 2/59 9335
/proc/meminfo: memFree=156140/1022884 swapFree=0/0
[pid=9316] ppid=9315 vsize=9212 CPUtime=7.63
/proc/9316/stat : 9316 (aspcud-basic) S 9315 9316 32685 0 -1 4202496 804 140419 0 0 0 0 710 53 20 0 1 0 37507442 9433088 365 18446744073709551615 4194304 5129932 140736100914528 140736100912592 140122625197150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9316/statm: 2303 365 303 229 0 63 0
[pid=9334] ppid=9316 vsize=205112 CPUtime=94.08
/proc/9334/stat : 9334 (clasp) R 9316 9316 32685 0 -1 4202496 56751 0 0 0 9392 16 0 0 20 0 1 0 37508211 210034688 50849 18446744073709551615 4194304 6238623 140735420735584 140735420732136 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9334/statm: 51278 50849 263 500 0 50775 0
[pid=9335] ppid=9316 vsize=22040 CPUtime=0.01
/proc/9335/stat : 9335 (parse.py) S 9316 9316 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37508211 22568960 1128 18446744073709551615 4194304 6642060 140734466904608 140734466902968 140622143244064 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9335/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.72
Current children cumulated vsize (KiB) 236364



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+150.9 s]
/proc/loadavg: 1.00 1.00 0.99 2/59 9335
/proc/meminfo: memFree=80748/1022884 swapFree=0/0
[pid=9316] ppid=9315 vsize=9212 CPUtime=7.63
/proc/9316/stat : 9316 (aspcud-basic) S 9315 9316 32685 0 -1 4202496 804 140419 0 0 0 0 710 53 20 0 1 0 37507442 9433088 365 18446744073709551615 4194304 5129932 140736100914528 140736100912592 140122625197150 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/9316/statm: 2303 365 303 229 0 63 0
[pid=9334] ppid=9316 vsize=280408 CPUtime=142.41
/proc/9334/stat : 9334 (clasp) R 9316 9316 32685 0 -1 4202496 75569 0 0 0 14215 26 0 0 20 0 1 0 37508211 287137792 69667 18446744073709551615 4194304 6238623 140735420735584 140735420732608 4676718 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/9334/statm: 70102 69667 263 500 0 69599 0
[pid=9335] ppid=9316 vsize=22040 CPUtime=0.01
/proc/9335/stat : 9335 (parse.py) S 9316 9316 32685 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 37508211 22568960 1128 18446744073709551615 4194304 6642060 140734466904608 140734466902968 140622143244064 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/9335/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.05
Current children cumulated vsize (KiB) 311660

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

Child status: 0
Real time (s): 150.939
CPU time (s): 150.129
CPU user time (s): 149.285
CPU system time (s): 0.844052
CPU usage (%): 99.4636
Max. virtual memory (cumulated for all children) (KiB): 417204

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.285
system time used= 0.844052
maximum resident set size= 352816
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 218412
page faults= 0
swaps= 0
block input operations= 0
block output operations= 47272
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 58
involuntary context switches= 2251

runsolver used 0.252015 second user time and 0.552034 second system time

The end