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/rand984.cudf.log.runsolver /home/competition/aspcud-basic-1.7/aspcud-basic /home/competition/data/install/rand984.cudf /tmp/misc2012/2012-09-02-17:21/basic/aspcud-basic-1.7/embedded/install/rand984.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

[startup+0 s]
/proc/loadavg: 0.87 0.93 0.95 2/59 5268
/proc/meminfo: memFree=403072/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=3152 CPUtime=0
/proc/5268/stat : 5268 (runsolver) R 5267 1750 1750 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115749612 3227648 32 18446744073709551615 134512640 134586868 4290134224 4290132272 4152128560 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.12983 s]
/proc/loadavg: 0.87 0.93 0.95 2/59 5268
/proc/meminfo: memFree=403072/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=9212 CPUtime=0.03
/proc/5268/stat : 5268 (aspcud-basic) S 5267 5268 1750 0 -1 4202496 729 3616 0 0 0 0 2 1 20 0 1 0 115749612 9433088 364 18446744073709551615 4194304 5129932 140735842336000 140735842334656 139751193613406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.20027 s]
/proc/loadavg: 0.87 0.93 0.95 2/59 5268
/proc/meminfo: memFree=403072/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=9212 CPUtime=0.03
/proc/5268/stat : 5268 (aspcud-basic) S 5267 5268 1750 0 -1 4202496 729 3616 0 0 0 0 2 1 20 0 1 0 115749612 9433088 364 18446744073709551615 4194304 5129932 140735842336000 140735842334656 139751193613406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.300287 s]
/proc/loadavg: 0.87 0.93 0.95 2/59 5268
/proc/meminfo: memFree=403072/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=9212 CPUtime=0.03
/proc/5268/stat : 5268 (aspcud-basic) S 5267 5268 1750 0 -1 4202496 729 3616 0 0 0 0 2 1 20 0 1 0 115749612 9433088 364 18446744073709551615 4194304 5129932 140735842336000 140735842334656 139751193613406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+0.700202 s]
/proc/loadavg: 0.87 0.93 0.95 2/59 5268
/proc/meminfo: memFree=403072/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=9212 CPUtime=0.03
/proc/5268/stat : 5268 (aspcud-basic) S 5267 5268 1750 0 -1 4202496 729 3616 0 0 0 0 2 1 20 0 1 0 115749612 9433088 364 18446744073709551615 4194304 5129932 140735842336000 140735842334656 139751193613406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 2303 364 303 229 0 63 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 9212

[startup+1.50027 s]
/proc/loadavg: 0.87 0.93 0.95 2/61 5284
/proc/meminfo: memFree=344032/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=9212 CPUtime=0.03
/proc/5268/stat : 5268 (aspcud-basic) S 5267 5268 1750 0 -1 4202496 729 3616 0 0 0 0 2 1 20 0 1 0 115749612 9433088 364 18446744073709551615 4194304 5129932 140735842336000 140735842334656 139751193613406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 2303 364 303 229 0 63 0
[pid=5284] ppid=5268 vsize=50676 CPUtime=1.45
/proc/5284/stat : 5284 (cudf2lp) R 5268 5268 1750 0 -1 4202496 15185 0 0 0 139 6 0 0 20 0 1 0 115749615 51892224 11787 18446744073709551615 4194304 5690517 140734949858096 140734949855736 4378360 0 0 16781316 0 0 0 0 17 0 0 0 1 0 0
/proc/5284/statm: 12669 11787 160 366 0 12300 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 59888

[startup+3.10026 s]
/proc/loadavg: 0.87 0.93 0.95 2/61 5284
/proc/meminfo: memFree=291208/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=9212 CPUtime=0.03
/proc/5268/stat : 5268 (aspcud-basic) S 5267 5268 1750 0 -1 4202496 729 3616 0 0 0 0 2 1 20 0 1 0 115749612 9433088 364 18446744073709551615 4194304 5129932 140735842336000 140735842334656 139751193613406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 2303 364 303 229 0 63 0
[pid=5284] ppid=5268 vsize=114764 CPUtime=3
/proc/5284/stat : 5284 (cudf2lp) R 5268 5268 1750 0 -1 4202496 39319 0 0 0 284 16 0 0 20 0 1 0 115749615 117518336 28363 18446744073709551615 4194304 5690517 140734949858096 140734949855432 5058496 0 0 16781316 0 0 0 0 17 0 0 0 5 0 0
/proc/5284/statm: 28691 28363 174 366 0 28322 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 123976

[startup+6.30026 s]
/proc/loadavg: 0.88 0.93 0.95 2/61 5285
/proc/meminfo: memFree=197836/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=9212 CPUtime=3.19
/proc/5268/stat : 5268 (aspcud-basic) S 5267 5268 1750 0 -1 4202496 755 42937 0 0 0 0 300 19 20 0 1 0 115749612 9433088 364 18446744073709551615 4194304 5129932 140735842336000 140735842334656 139751193613406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 2303 364 303 229 0 63 0
[pid=5285] ppid=5268 vsize=280404 CPUtime=3.01
/proc/5285/stat : 5285 (gringo) R 5268 5268 1750 0 -1 4202496 68517 0 0 0 282 19 0 0 20 0 1 0 115749938 287133696 59238 18446744073709551615 4194304 6531320 140737305730640 140737305727256 4593498 0 0 16781316 16386 0 0 0 17 0 0 0 0 0 0
/proc/5285/statm: 70101 59238 282 571 0 69522 0
Current children cumulated CPU time (s) 6.2
Current children cumulated vsize (KiB) 289616

[startup+12.7004 s]
/proc/loadavg: 0.89 0.93 0.95 2/62 5287
/proc/meminfo: memFree=248676/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=9212 CPUtime=7.76
/proc/5268/stat : 5268 (aspcud-basic) S 5267 5268 1750 0 -1 4202496 795 145297 0 0 0 0 716 60 20 0 1 0 115749612 9433088 364 18446744073709551615 4194304 5129932 140735842336000 140735842334064 139751193613406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 2303 364 303 229 0 63 0
[pid=5286] ppid=5268 vsize=133468 CPUtime=4.73
/proc/5286/stat : 5286 (clasp) R 5268 5268 1750 0 -1 4202496 38851 0 0 0 466 7 0 0 20 0 1 0 115750404 136671232 32857 18446744073709551615 4194304 6238623 140736540502832 140736540499856 4409910 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5286/statm: 33367 32857 263 500 0 32864 0
[pid=5287] ppid=5268 vsize=22040 CPUtime=0.01
/proc/5287/stat : 5287 (parse.py) S 5268 5268 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 115750404 22568960 1128 18446744073709551615 4194304 6642060 140736520433376 140736520431736 140310036793120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5287/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 12.5
Current children cumulated vsize (KiB) 164720

[startup+25.5004 s]
/proc/loadavg: 0.91 0.93 0.95 2/62 5287
/proc/meminfo: memFree=248676/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=9212 CPUtime=7.76
/proc/5268/stat : 5268 (aspcud-basic) S 5267 5268 1750 0 -1 4202496 795 145297 0 0 0 0 716 60 20 0 1 0 115749612 9433088 364 18446744073709551615 4194304 5129932 140735842336000 140735842334064 139751193613406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 2303 364 303 229 0 63 0
[pid=5286] ppid=5268 vsize=133468 CPUtime=17.4
/proc/5286/stat : 5286 (clasp) R 5268 5268 1750 0 -1 4202496 38851 0 0 0 1733 7 0 0 20 0 1 0 115750404 136671232 32857 18446744073709551615 4194304 6238623 140736540502832 140736540499856 4421752 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5286/statm: 33367 32857 263 500 0 32864 0
[pid=5287] ppid=5268 vsize=22040 CPUtime=0.01
/proc/5287/stat : 5287 (parse.py) S 5268 5268 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 115750404 22568960 1128 18446744073709551615 4194304 6642060 140736520433376 140736520431736 140310036793120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5287/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 25.17
Current children cumulated vsize (KiB) 164720

[startup+51.1004 s]
/proc/loadavg: 0.94 0.94 0.95 2/62 5287
/proc/meminfo: memFree=248676/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=9212 CPUtime=7.76
/proc/5268/stat : 5268 (aspcud-basic) S 5267 5268 1750 0 -1 4202496 795 145297 0 0 0 0 716 60 20 0 1 0 115749612 9433088 364 18446744073709551615 4194304 5129932 140735842336000 140735842334064 139751193613406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 2303 364 303 229 0 63 0
[pid=5286] ppid=5268 vsize=133468 CPUtime=42.78
/proc/5286/stat : 5286 (clasp) R 5268 5268 1750 0 -1 4202496 38851 0 0 0 4271 7 0 0 20 0 1 0 115750404 136671232 32857 18446744073709551615 4194304 6238623 140736540502832 140736540499856 4331904 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5286/statm: 33367 32857 263 500 0 32864 0
[pid=5287] ppid=5268 vsize=22040 CPUtime=0.01
/proc/5287/stat : 5287 (parse.py) S 5268 5268 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 115750404 22568960 1128 18446744073709551615 4194304 6642060 140736520433376 140736520431736 140310036793120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5287/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 50.55
Current children cumulated vsize (KiB) 164720

[startup+102.3 s]
/proc/loadavg: 0.97 0.94 0.95 2/62 5287
/proc/meminfo: memFree=247932/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=9212 CPUtime=7.76
/proc/5268/stat : 5268 (aspcud-basic) S 5267 5268 1750 0 -1 4202496 795 145297 0 0 0 0 716 60 20 0 1 0 115749612 9433088 364 18446744073709551615 4194304 5129932 140735842336000 140735842334064 139751193613406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 2303 364 303 229 0 63 0
[pid=5286] ppid=5268 vsize=133468 CPUtime=93.5
/proc/5286/stat : 5286 (clasp) R 5268 5268 1750 0 -1 4202496 39035 0 0 0 9343 7 0 0 20 0 1 0 115750404 136671232 33041 18446744073709551615 4194304 6238623 140736540502832 140736540499856 4676789 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5286/statm: 33367 33041 263 500 0 32864 0
[pid=5287] ppid=5268 vsize=22040 CPUtime=0.01
/proc/5287/stat : 5287 (parse.py) S 5268 5268 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 115750404 22568960 1128 18446744073709551615 4194304 6642060 140736520433376 140736520431736 140310036793120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5287/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 101.27
Current children cumulated vsize (KiB) 164720



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.4 s]
/proc/loadavg: 0.99 0.95 0.95 2/62 5287
/proc/meminfo: memFree=181592/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=9212 CPUtime=7.76
/proc/5268/stat : 5268 (aspcud-basic) S 5267 5268 1750 0 -1 4202496 795 145297 0 0 0 0 716 60 20 0 1 0 115749612 9433088 364 18446744073709551615 4194304 5129932 140735842336000 140735842334064 139751193613406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 2303 364 303 229 0 63 0
[pid=5286] ppid=5268 vsize=200064 CPUtime=142.25
/proc/5286/stat : 5286 (clasp) R 5268 5268 1750 0 -1 4202496 55587 0 0 0 14211 14 0 0 20 0 1 0 115750404 204865536 49593 18446744073709551615 4194304 6238623 140736540502832 140736540499384 4413000 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5286/statm: 50016 49593 263 500 0 49513 0
[pid=5287] ppid=5268 vsize=22040 CPUtime=0.01
/proc/5287/stat : 5287 (parse.py) S 5268 5268 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 115750404 22568960 1128 18446744073709551615 4194304 6642060 140736520433376 140736520431736 140310036793120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5287/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.02
Current children cumulated vsize (KiB) 231316

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

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

[startup+151.4 s]
/proc/loadavg: 0.99 0.95 0.95 2/62 5287
/proc/meminfo: memFree=181592/1022884 swapFree=0/0
[pid=5268] ppid=5267 vsize=9212 CPUtime=7.76
/proc/5268/stat : 5268 (aspcud-basic) S 5267 5268 1750 0 -1 4202496 795 145297 0 0 0 0 716 60 20 0 1 0 115749612 9433088 364 18446744073709551615 4194304 5129932 140735842336000 140735842334064 139751193613406 0 65536 16781316 1115778811 0 0 0 17 0 0 0 0 0 0
/proc/5268/statm: 2303 364 303 229 0 63 0
[pid=5286] ppid=5268 vsize=200064 CPUtime=142.25
/proc/5286/stat : 5286 (clasp) R 5268 5268 1750 0 -1 4202496 55587 0 0 0 14211 14 0 0 20 0 1 0 115750404 204865536 49593 18446744073709551615 4194304 6238623 140736540502832 140736540499384 4413000 0 0 16781316 18946 0 0 0 17 0 0 0 0 0 0
/proc/5286/statm: 50016 49593 263 500 0 49513 0
[pid=5287] ppid=5268 vsize=22040 CPUtime=0.01
/proc/5287/stat : 5287 (parse.py) S 5268 5268 1750 0 -1 4202496 1318 0 0 0 0 1 0 0 20 0 1 0 115750404 22568960 1128 18446744073709551615 4194304 6642060 140736520433376 140736520431736 140310036793120 0 0 16777220 20994 0 0 0 17 0 0 0 0 0 0
/proc/5287/statm: 5510 1128 508 598 0 596 0
Current children cumulated CPU time (s) 150.02
Current children cumulated vsize (KiB) 231316

Child status: 0
Real time (s): 151.454
CPU time (s): 150.073
CPU user time (s): 149.281
CPU system time (s): 0.792049
CPU usage (%): 99.0887
Max. virtual memory (cumulated for all children) (KiB): 436440

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.281
system time used= 0.792049
maximum resident set size= 372308
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 203299
page faults= 1
swaps= 0
block input operations= 68472
block output operations= 49432
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 79
involuntary context switches= 17243

runsolver used 0.49203 second user time and 0.464029 second system time

The end