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/8680dd8a-8600-11e0-b285-00163e1e087d.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/real/8680dd8a-8600-11e0-b285-00163e1e087d.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/real/8680dd8a-8600-11e0-b285-00163e1e087d.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: 1.09 1.04 1.01 2/64 5340
/proc/meminfo: memFree=154820/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=3152 CPUtime=0
/proc/5340/stat : 5340 (runsolver) R 5339 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115622848 3227648 32 18446744073709551615 134512640 134586868 4293822160 4293820208 4151362608 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/5340/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.142286 s]
/proc/loadavg: 1.09 1.04 1.01 2/64 5340
/proc/meminfo: memFree=154820/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=9964 CPUtime=0.1
/proc/5340/stat : 5340 (cudf_fumax_bu-0) D 5339 5340 1745 0 -1 4202496 2212 0 0 0 10 0 0 0 20 0 1 0 115622848 10203136 2134 18446744073709551615 4194304 5895655 140735791749440 140735791745352 5193680 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/5340/statm: 2491 2134 149 416 0 2072 0
Current children cumulated CPU time (s) 0.1
Current children cumulated vsize (KiB) 9964

[startup+0.200324 s]
/proc/loadavg: 1.09 1.04 1.01 2/64 5340
/proc/meminfo: memFree=154820/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=12352 CPUtime=0.14
/proc/5340/stat : 5340 (cudf_fumax_bu-0) R 5339 5340 1745 0 -1 4202496 2835 0 0 0 14 0 0 0 20 0 1 0 115622848 12648448 2757 18446744073709551615 4194304 5895655 140735791749440 140735791745352 5302337 0 0 16781316 16929 0 0 0 17 0 0 0 4 0 0
/proc/5340/statm: 3088 2757 149 416 0 2669 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 12352

[startup+0.300416 s]
/proc/loadavg: 1.09 1.04 1.01 2/64 5340
/proc/meminfo: memFree=154820/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=15520 CPUtime=0.19
/proc/5340/stat : 5340 (cudf_fumax_bu-0) D 5339 5340 1745 0 -1 4202496 3621 0 0 0 18 1 0 0 20 0 1 0 115622848 15892480 3543 18446744073709551615 4194304 5895655 140735791749440 140735791745352 5193680 0 0 16781316 16929 0 0 0 17 0 0 0 5 0 0
/proc/5340/statm: 3880 3543 149 416 0 3461 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 15520

[startup+0.700218 s]
/proc/loadavg: 1.09 1.04 1.01 2/64 5340
/proc/meminfo: memFree=154820/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=35120 CPUtime=0.54
/proc/5340/stat : 5340 (cudf_fumax_bu-0) R 5339 5340 1745 0 -1 4202496 8567 0 0 0 50 4 0 0 20 0 1 0 115622848 35962880 8440 18446744073709551615 4194304 5895655 140735791749440 140735791745352 4775563 0 0 16781316 16929 0 0 0 17 0 0 0 15 0 0
/proc/5340/statm: 8780 8440 149 416 0 8361 0
Current children cumulated CPU time (s) 0.54
Current children cumulated vsize (KiB) 35120

[startup+1.50023 s]
/proc/loadavg: 1.08 1.04 1.01 2/65 5341
/proc/meminfo: memFree=86108/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=78908 CPUtime=1.28
/proc/5340/stat : 5340 (cudf_fumax_bu-0) R 5339 5340 1745 0 -1 4202496 19616 0 0 0 120 8 0 0 20 0 1 0 115622848 80801792 18507 18446744073709551615 4194304 5895655 140735791749440 140735791744296 5093799 0 0 16781316 16929 0 0 0 17 0 0 0 19 0 0
/proc/5340/statm: 19727 18507 195 416 0 19308 0
Current children cumulated CPU time (s) 1.28
Current children cumulated vsize (KiB) 78908

[startup+3.10021 s]
/proc/loadavg: 1.08 1.04 1.01 2/65 5341
/proc/meminfo: memFree=62176/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=78908 CPUtime=2.87
/proc/5340/stat : 5340 (cudf_fumax_bu-0) R 5339 5340 1745 0 -1 4202496 19619 0 0 0 278 9 0 0 20 0 1 0 115622848 80801792 18510 18446744073709551615 4194304 5895655 140735791749440 140735791744296 4452112 0 0 16781316 16929 0 0 0 17 0 0 0 19 0 0
/proc/5340/statm: 19727 18510 195 416 0 19308 0
Current children cumulated CPU time (s) 2.87
Current children cumulated vsize (KiB) 78908

[startup+6.30022 s]
/proc/loadavg: 1.08 1.04 1.01 2/65 5341
/proc/meminfo: memFree=62052/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=78908 CPUtime=5.99
/proc/5340/stat : 5340 (cudf_fumax_bu-0) R 5339 5340 1745 0 -1 4202496 19646 0 0 0 588 11 0 0 20 0 1 0 115622848 80801792 18537 18446744073709551615 4194304 5895655 140735791749440 140735791744296 4472943 0 0 16781316 16929 0 0 0 17 0 0 0 25 0 0
/proc/5340/statm: 19727 18537 195 416 0 19308 0
Current children cumulated CPU time (s) 5.99
Current children cumulated vsize (KiB) 78908

[startup+12.7002 s]
/proc/loadavg: 1.07 1.03 1.01 2/65 5341
/proc/meminfo: memFree=61804/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=79120 CPUtime=12.34
/proc/5340/stat : 5340 (cudf_fumax_bu-0) R 5339 5340 1745 0 -1 4202496 19701 0 0 0 1218 16 0 0 20 0 1 0 115622848 81018880 18592 18446744073709551615 4194304 5895655 140735791749440 140735791744296 5094686 0 0 16781316 16929 0 0 0 17 0 0 0 25 0 0
/proc/5340/statm: 19780 18592 195 416 0 19361 0
Current children cumulated CPU time (s) 12.34
Current children cumulated vsize (KiB) 79120

[startup+25.5002 s]
/proc/loadavg: 1.06 1.03 1.01 2/65 5341
/proc/meminfo: memFree=60316/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=80604 CPUtime=25.03
/proc/5340/stat : 5340 (cudf_fumax_bu-0) R 5339 5340 1745 0 -1 4202496 20125 0 0 0 2484 19 0 0 20 0 1 0 115622848 82538496 19016 18446744073709551615 4194304 5895655 140735791749440 140735791744296 4436271 0 0 16781316 16929 0 0 0 17 0 0 0 25 0 0
/proc/5340/statm: 20151 19016 195 416 0 19732 0
Current children cumulated CPU time (s) 25.03
Current children cumulated vsize (KiB) 80604

[startup+51.1003 s]
/proc/loadavg: 1.04 1.03 1.01 2/65 5341
/proc/meminfo: memFree=58084/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=82504 CPUtime=50.42
/proc/5340/stat : 5340 (cudf_fumax_bu-0) R 5339 5340 1745 0 -1 4202496 20573 0 0 0 5018 24 0 0 20 0 1 0 115622848 84484096 19464 18446744073709551615 4194304 5895655 140735791749440 140735791744296 4472989 0 0 16781316 16929 0 0 0 17 0 0 0 30 0 0
/proc/5340/statm: 20626 19464 195 416 0 20207 0
Current children cumulated CPU time (s) 50.42
Current children cumulated vsize (KiB) 82504

[startup+102.3 s]
/proc/loadavg: 1.01 1.02 1.00 2/65 5341
/proc/meminfo: memFree=47296/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=93252 CPUtime=101.1
/proc/5340/stat : 5340 (cudf_fumax_bu-0) R 5339 5340 1745 0 -1 4202496 23378 0 0 0 10080 30 0 0 20 0 1 0 115622848 95490048 22102 18446744073709551615 4194304 5895655 140735791749440 140735791744296 5082018 0 0 16781316 16929 0 0 0 17 0 0 0 41 0 0
/proc/5340/statm: 23313 22102 195 416 0 22894 0
Current children cumulated CPU time (s) 101.1
Current children cumulated vsize (KiB) 93252



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.8 s]
/proc/loadavg: 1.00 1.02 1.00 2/65 5341
/proc/meminfo: memFree=38368/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=100904 CPUtime=150.08
/proc/5340/stat : 5340 (cudf_fumax_bu-0) R 5339 5340 1745 0 -1 4202496 759372 0 0 0 14723 285 0 0 20 0 1 0 115622848 103325696 24310 18446744073709551615 4194304 5895655 140735791749440 140735791743224 5073448 0 0 16781316 16929 0 0 0 17 0 0 0 57 0 0
/proc/5340/statm: 25226 24310 195 416 0 24807 0
Current children cumulated CPU time (s) 150.08
Current children cumulated vsize (KiB) 100904

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

Sending SIGKILL to process tree (bottom up)

Sending SIGKILL to -5340

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

[startup+153.5 s]
/proc/loadavg: 1.00 1.02 1.00 2/66 5342
/proc/meminfo: memFree=47412/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=88900 CPUtime=150.09
/proc/5340/stat : 5340 (cudf_fumax_bu-0) S 5339 5340 1745 0 -1 4202496 759372 0 0 0 14724 285 0 0 20 0 1 0 115622848 91033600 21883 18446744073709551615 4194304 5895655 140735791749440 140735791741672 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 57 0 0
/proc/5340/statm: 22225 21883 195 416 0 21806 0
Current children cumulated CPU time (s) 150.09
Current children cumulated vsize (KiB) 88900

[startup+156.7 s]
/proc/loadavg: 0.92 1.00 0.99 1/66 5342
/proc/meminfo: memFree=47412/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=88900 CPUtime=150.09
/proc/5340/stat : 5340 (cudf_fumax_bu-0) S 5339 5340 1745 0 -1 4202496 759372 0 0 0 14724 285 0 0 20 0 1 0 115622848 91033600 21883 18446744073709551615 4194304 5895655 140735791749440 140735791741672 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 57 0 0
/proc/5340/statm: 22225 21883 195 416 0 21806 0
Current children cumulated CPU time (s) 150.09
Current children cumulated vsize (KiB) 88900

[startup+159.9 s]
/proc/loadavg: 0.92 1.00 0.99 1/66 5342
/proc/meminfo: memFree=47412/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=88900 CPUtime=150.09
/proc/5340/stat : 5340 (cudf_fumax_bu-0) S 5339 5340 1745 0 -1 4202496 759372 0 0 0 14724 285 0 0 20 0 1 0 115622848 91033600 21883 18446744073709551615 4194304 5895655 140735791749440 140735791741672 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 57 0 0
/proc/5340/statm: 22225 21883 195 416 0 21806 0
Current children cumulated CPU time (s) 150.09
Current children cumulated vsize (KiB) 88900

[startup+160.705 s]
/proc/loadavg: 0.92 1.00 0.99 1/66 5342
/proc/meminfo: memFree=47412/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=88900 CPUtime=150.09
/proc/5340/stat : 5340 (cudf_fumax_bu-0) S 5339 5340 1745 0 -1 4202496 759372 0 0 0 14724 285 0 0 20 0 1 0 115622848 91033600 21883 18446744073709551615 4194304 5895655 140735791749440 140735791741672 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 57 0 0
/proc/5340/statm: 22225 21883 195 416 0 21806 0
Current children cumulated CPU time (s) 150.09
Current children cumulated vsize (KiB) 88900

[startup+161.5 s]
/proc/loadavg: 0.92 1.00 0.99 1/66 5342
/proc/meminfo: memFree=47412/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=88900 CPUtime=150.09
/proc/5340/stat : 5340 (cudf_fumax_bu-0) S 5339 5340 1745 0 -1 4202496 759372 0 0 0 14724 285 0 0 20 0 1 0 115622848 91033600 21883 18446744073709551615 4194304 5895655 140735791749440 140735791741672 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 57 0 0
/proc/5340/statm: 22225 21883 195 416 0 21806 0
Current children cumulated CPU time (s) 150.09
Current children cumulated vsize (KiB) 88900

[startup+161.7 s]
/proc/loadavg: 0.85 0.98 0.99 1/66 5342
/proc/meminfo: memFree=47536/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=88900 CPUtime=150.09
/proc/5340/stat : 5340 (cudf_fumax_bu-0) S 5339 5340 1745 0 -1 4202496 759372 0 0 0 14724 285 0 0 20 0 1 0 115622848 91033600 21883 18446744073709551615 4194304 5895655 140735791749440 140735791741672 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 57 0 0
/proc/5340/statm: 22225 21883 195 416 0 21806 0
Current children cumulated CPU time (s) 150.09
Current children cumulated vsize (KiB) 88900

[startup+161.805 s]
/proc/loadavg: 0.85 0.98 0.99 1/66 5342
/proc/meminfo: memFree=47536/1022884 swapFree=0/0
[pid=5340] ppid=5339 vsize=88900 CPUtime=150.09
/proc/5340/stat : 5340 (cudf_fumax_bu-0) S 5339 5340 1745 0 -1 4202496 759372 0 0 0 14724 285 0 0 20 0 1 0 115622848 91033600 21883 18446744073709551615 4194304 5895655 140735791749440 140735791741672 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 57 0 0
/proc/5340/statm: 22225 21883 195 416 0 21806 0
Current children cumulated CPU time (s) 150.09
Current children cumulated vsize (KiB) 88900

Child ended because it received signal 9 (SIGKILL)
Real time (s): 161.828
CPU time (s): 150.109
CPU user time (s): 147.241
CPU system time (s): 2.86818
CPU usage (%): 92.7585
Max. virtual memory (cumulated for all children) (KiB): 100904

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 147.241
system time used= 2.86818
maximum resident set size= 97368
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 759372
page faults= 0
swaps= 0
block input operations= 38336
block output operations= 520
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 83
involuntary context switches= 17083

runsolver used 0.248015 second user time and 0.580036 second system time

The end