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/cudf_fumax_bu-0.1/paranoid-size/real/26f3d4cc-d470-11df-9e6c-00163e3d3b7c.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/real/26f3d4cc-d470-11df-9e6c-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/real/26f3d4cc-d470-11df-9e6c-00163e3d3b7c.cudf.result -count(removed),-sum(solution,installedsize),-count(changed) 

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.91 0.93 0.96 2/59 22464
/proc/meminfo: memFree=249020/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=3152 CPUtime=0
/proc/22464/stat : 22464 (runsolver) R 22463 1733 1733 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115586059 3227648 33 18446744073709551615 134512640 134586868 4286952336 4286950384 4151964720 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/22464/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.180946 s]
/proc/loadavg: 0.91 0.93 0.96 2/59 22464
/proc/meminfo: memFree=249020/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=8956 CPUtime=0.15
/proc/22464/stat : 22464 (cudf_fumax_bu-0) R 22463 22464 1733 0 -1 4202496 1955 0 0 0 14 1 0 0 20 0 1 0 115586059 9170944 1877 18446744073709551615 4194304 5895655 140737394648688 140737394644600 4346857 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/22464/statm: 2239 1877 149 416 0 1820 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 8956

[startup+0.200327 s]
/proc/loadavg: 0.91 0.93 0.96 2/59 22464
/proc/meminfo: memFree=249020/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=9616 CPUtime=0.17
/proc/22464/stat : 22464 (cudf_fumax_bu-0) R 22463 22464 1733 0 -1 4202496 2144 0 0 0 16 1 0 0 20 0 1 0 115586059 9846784 2066 18446744073709551615 4194304 5895655 140737394648688 140737394644600 5296966 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/22464/statm: 2404 2066 149 416 0 1985 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 9616

[startup+0.300311 s]
/proc/loadavg: 0.91 0.93 0.96 2/59 22464
/proc/meminfo: memFree=249020/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=13588 CPUtime=0.26
/proc/22464/stat : 22464 (cudf_fumax_bu-0) R 22463 22464 1733 0 -1 4202496 3114 0 0 0 24 2 0 0 20 0 1 0 115586059 13914112 3036 18446744073709551615 4194304 5895655 140737394648688 140737394644456 4347082 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/22464/statm: 3397 3036 149 416 0 2978 0
Current children cumulated CPU time (s) 0.26
Current children cumulated vsize (KiB) 13588

[startup+0.700247 s]
/proc/loadavg: 0.91 0.93 0.96 2/59 22464
/proc/meminfo: memFree=249020/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=27440 CPUtime=0.66
/proc/22464/stat : 22464 (cudf_fumax_bu-0) R 22463 22464 1733 0 -1 4202496 6640 0 0 0 62 4 0 0 20 0 1 0 115586059 28098560 6513 18446744073709551615 4194304 5895655 140737394648688 140737394644600 4349635 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/22464/statm: 6860 6513 149 416 0 6441 0
Current children cumulated CPU time (s) 0.66
Current children cumulated vsize (KiB) 27440

[startup+1.50023 s]
/proc/loadavg: 0.91 0.93 0.96 2/60 22465
/proc/meminfo: memFree=195768/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=51720 CPUtime=1.46
/proc/22464/stat : 22464 (cudf_fumax_bu-0) R 22463 22464 1733 0 -1 4202496 12776 0 0 0 138 8 0 0 20 0 1 0 115586059 52961280 12503 18446744073709551615 4194304 5895655 140737394648688 140737394644296 4239488 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/22464/statm: 12930 12503 165 416 0 12511 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 51720

[startup+3.10027 s]
/proc/loadavg: 0.91 0.93 0.96 2/60 22465
/proc/meminfo: memFree=160164/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=73604 CPUtime=3.04
/proc/22464/stat : 22464 (cudf_fumax_bu-0) R 22463 22464 1733 0 -1 4202496 18581 0 0 0 292 12 0 0 20 0 1 0 115586059 75370496 17402 18446744073709551615 4194304 5895655 140737394648688 140737394643544 4473021 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/22464/statm: 18401 17402 195 416 0 17982 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 73604

[startup+6.30023 s]
/proc/loadavg: 0.91 0.93 0.96 2/60 22465
/proc/meminfo: memFree=160040/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=73760 CPUtime=6.21
/proc/22464/stat : 22464 (cudf_fumax_bu-0) R 22463 22464 1733 0 -1 4202496 18645 0 0 0 607 14 0 0 20 0 1 0 115586059 75530240 17451 18446744073709551615 4194304 5895655 140737394648688 140737394643544 4447947 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/22464/statm: 18440 17451 195 416 0 18021 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 73760

[startup+12.7002 s]
/proc/loadavg: 1.00 0.95 0.96 2/60 22465
/proc/meminfo: memFree=159668/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=73760 CPUtime=12.55
/proc/22464/stat : 22464 (cudf_fumax_bu-0) R 22463 22464 1733 0 -1 4202496 18668 0 0 0 1240 15 0 0 20 0 1 0 115586059 75530240 17474 18446744073709551615 4194304 5895655 140737394648688 140737394643480 5193776 0 0 16781316 16929 0 0 0 17 0 0 0 4 0 0
/proc/22464/statm: 18440 17474 195 416 0 18021 0
Current children cumulated CPU time (s) 12.55
Current children cumulated vsize (KiB) 73760

[startup+25.5003 s]
/proc/loadavg: 1.00 0.95 0.96 2/60 22465
/proc/meminfo: memFree=158552/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=74900 CPUtime=25.22
/proc/22464/stat : 22464 (cudf_fumax_bu-0) R 22463 22464 1733 0 -1 4202496 19040 0 0 0 2504 18 0 0 20 0 1 0 115586059 76697600 17770 18446744073709551615 4194304 5895655 140737394648688 140737394643544 4456626 0 0 16781316 16929 0 0 0 17 0 0 0 6 0 0
/proc/22464/statm: 18725 17770 195 416 0 18306 0
Current children cumulated CPU time (s) 25.22
Current children cumulated vsize (KiB) 74900

[startup+51.1002 s]
/proc/loadavg: 1.00 0.95 0.96 2/60 22465
/proc/meminfo: memFree=157436/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=75692 CPUtime=50.64
/proc/22464/stat : 22464 (cudf_fumax_bu-0) R 22463 22464 1733 0 -1 4202496 19352 0 0 0 5038 26 0 0 20 0 1 0 115586059 77508608 18020 18446744073709551615 4194304 5895655 140737394648688 140737394643544 4446987 0 0 16781316 16929 0 0 0 17 0 0 0 7 0 0
/proc/22464/statm: 18923 18020 195 416 0 18504 0
Current children cumulated CPU time (s) 50.64
Current children cumulated vsize (KiB) 75692

[startup+102.3 s]
/proc/loadavg: 1.00 0.96 0.96 2/60 22465
/proc/meminfo: memFree=152352/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=80024 CPUtime=101.45
/proc/22464/stat : 22464 (cudf_fumax_bu-0) R 22463 22464 1733 0 -1 4202496 20847 0 0 0 10109 36 0 0 20 0 1 0 115586059 81944576 19244 18446744073709551615 4194304 5895655 140737394648688 140737394643544 5084734 0 0 16781316 16929 0 0 0 17 0 0 0 9 0 0
/proc/22464/statm: 20006 19244 195 416 0 19587 0
Current children cumulated CPU time (s) 101.45
Current children cumulated vsize (KiB) 80024



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.3 s]
/proc/loadavg: 1.00 0.96 0.96 2/60 22465
/proc/meminfo: memFree=142060/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=90216 CPUtime=150.06
/proc/22464/stat : 22464 (cudf_fumax_bu-0) R 22463 22464 1733 0 -1 4202496 23823 0 0 0 14964 42 0 0 20 0 1 0 115586059 92381184 21757 18446744073709551615 4194304 5895655 140737394648688 140737394643544 5073382 0 0 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/22464/statm: 22554 21757 208 416 0 22135 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 90216

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

Sending SIGKILL to process tree (bottom up)

Sending SIGKILL to -22464

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

[startup+153.5 s]
/proc/loadavg: 1.00 0.96 0.96 1/61 22466
/proc/meminfo: memFree=142052/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=90216 CPUtime=150.06
/proc/22464/stat : 22464 (cudf_fumax_bu-0) S 22463 22464 1733 0 -1 4202496 23823 0 0 0 14964 42 0 0 20 0 1 0 115586059 92381184 21757 18446744073709551615 4194304 5895655 140737394648688 140737394640872 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/22464/statm: 22554 21757 208 416 0 22135 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 90216

[startup+156.7 s]
/proc/loadavg: 0.92 0.95 0.96 1/61 22466
/proc/meminfo: memFree=142052/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=90216 CPUtime=150.06
/proc/22464/stat : 22464 (cudf_fumax_bu-0) S 22463 22464 1733 0 -1 4202496 23823 0 0 0 14964 42 0 0 20 0 1 0 115586059 92381184 21757 18446744073709551615 4194304 5895655 140737394648688 140737394640872 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/22464/statm: 22554 21757 208 416 0 22135 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 90216

[startup+159.9 s]
/proc/loadavg: 0.85 0.93 0.95 1/61 22466
/proc/meminfo: memFree=142052/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=90216 CPUtime=150.06
/proc/22464/stat : 22464 (cudf_fumax_bu-0) S 22463 22464 1733 0 -1 4202496 23823 0 0 0 14964 42 0 0 20 0 1 0 115586059 92381184 21757 18446744073709551615 4194304 5895655 140737394648688 140737394640872 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/22464/statm: 22554 21757 208 416 0 22135 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 90216

[startup+160.704 s]
/proc/loadavg: 0.85 0.93 0.95 1/61 22466
/proc/meminfo: memFree=142052/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=90216 CPUtime=150.06
/proc/22464/stat : 22464 (cudf_fumax_bu-0) S 22463 22464 1733 0 -1 4202496 23823 0 0 0 14964 42 0 0 20 0 1 0 115586059 92381184 21757 18446744073709551615 4194304 5895655 140737394648688 140737394640872 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/22464/statm: 22554 21757 208 416 0 22135 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 90216

[startup+161.1 s]
/proc/loadavg: 0.85 0.93 0.95 1/61 22466
/proc/meminfo: memFree=142052/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=90216 CPUtime=150.06
/proc/22464/stat : 22464 (cudf_fumax_bu-0) S 22463 22464 1733 0 -1 4202496 23823 0 0 0 14964 42 0 0 20 0 1 0 115586059 92381184 21757 18446744073709551615 4194304 5895655 140737394648688 140737394640872 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/22464/statm: 22554 21757 208 416 0 22135 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 90216

[startup+161.3 s]
/proc/loadavg: 0.85 0.93 0.95 1/61 22466
/proc/meminfo: memFree=142052/1022884 swapFree=0/0
[pid=22464] ppid=22463 vsize=90216 CPUtime=150.06
/proc/22464/stat : 22464 (cudf_fumax_bu-0) S 22463 22464 1733 0 -1 4202496 23823 0 0 0 14964 42 0 0 20 0 1 0 115586059 92381184 21757 18446744073709551615 4194304 5895655 140737394648688 140737394640872 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 10 0 0
/proc/22464/statm: 22554 21757 208 416 0 22135 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 90216

Child ended because it received signal 9 (SIGKILL)
Real time (s): 161.319
CPU time (s): 150.081
CPU user time (s): 149.641
CPU system time (s): 0.440027
CPU usage (%): 93.0342
Max. virtual memory (cumulated for all children) (KiB): 90216

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.641
system time used= 0.440027
maximum resident set size= 87028
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 23823
page faults= 0
swaps= 0
block input operations= 39640
block output operations= 504
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 74
involuntary context switches= 17082

runsolver used 0.240015 second user time and 0.552034 second system time

The end