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/4a69cf16-c731-11df-9182-00163e3d3b7c.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/real/4a69cf16-c731-11df-9182-00163e3d3b7c.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/real/4a69cf16-c731-11df-9182-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.98 0.98 0.99 2/64 5370
/proc/meminfo: memFree=125804/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=3152 CPUtime=0
/proc/5370/stat : 5370 (runsolver) R 5369 1745 1745 0 -1 4202560 0 0 0 0 0 0 0 0 20 0 1 0 115651910 3227648 32 18446744073709551615 134512640 134586868 4286685088 4286683136 4151297072 0 0 16781316 24578 0 0 0 17 0 0 0 0 0 0
/proc/5370/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.132028 s]
/proc/loadavg: 0.98 0.98 0.99 2/64 5370
/proc/meminfo: memFree=125804/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=7340 CPUtime=0.1
/proc/5370/stat : 5370 (cudf_fumax_bu-0) R 5369 5370 1745 0 -1 4202496 1578 0 0 0 10 0 0 0 20 0 1 0 115651910 7516160 1501 18446744073709551615 4194304 5895655 140734745365696 140734745361608 4347147 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/5370/statm: 1835 1501 146 416 0 1416 0
Current children cumulated CPU time (s) 0.1
Current children cumulated vsize (KiB) 7340

[startup+0.200329 s]
/proc/loadavg: 0.98 0.98 0.99 2/64 5370
/proc/meminfo: memFree=125804/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=10176 CPUtime=0.17
/proc/5370/stat : 5370 (cudf_fumax_bu-0) R 5369 5370 1745 0 -1 4202496 2289 0 0 0 16 1 0 0 20 0 1 0 115651910 10420224 2212 18446744073709551615 4194304 5895655 140734745365696 140734745361608 4346931 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/5370/statm: 2544 2212 149 416 0 2125 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 10176

[startup+0.300321 s]
/proc/loadavg: 0.98 0.98 0.99 2/64 5370
/proc/meminfo: memFree=125804/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=14052 CPUtime=0.27
/proc/5370/stat : 5370 (cudf_fumax_bu-0) R 5369 5370 1745 0 -1 4202496 3258 0 0 0 25 2 0 0 20 0 1 0 115651910 14389248 3181 18446744073709551615 4194304 5895655 140734745365696 140734745361608 4347053 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/5370/statm: 3513 3181 149 416 0 3094 0
Current children cumulated CPU time (s) 0.27
Current children cumulated vsize (KiB) 14052

[startup+0.700246 s]
/proc/loadavg: 0.98 0.98 0.99 2/64 5370
/proc/meminfo: memFree=125804/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=28448 CPUtime=0.66
/proc/5370/stat : 5370 (cudf_fumax_bu-0) R 5369 5370 1745 0 -1 4202496 6900 0 0 0 62 4 0 0 20 0 1 0 115651910 29130752 6774 18446744073709551615 4194304 5895655 140734745365696 140734745361608 5084807 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/5370/statm: 7112 6774 149 416 0 6693 0
Current children cumulated CPU time (s) 0.66
Current children cumulated vsize (KiB) 28448

[startup+1.50024 s]
/proc/loadavg: 0.98 0.98 0.99 2/65 5371
/proc/meminfo: memFree=70484/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=52312 CPUtime=1.44
/proc/5370/stat : 5370 (cudf_fumax_bu-0) R 5369 5370 1745 0 -1 4202496 12915 0 0 0 136 8 0 0 20 0 1 0 115651910 53567488 12740 18446744073709551615 4194304 5895655 140734745365696 140734745361608 4383936 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/5370/statm: 13078 12740 149 416 0 12659 0
Current children cumulated CPU time (s) 1.44
Current children cumulated vsize (KiB) 52312

[startup+3.10024 s]
/proc/loadavg: 0.98 0.98 0.99 2/65 5371
/proc/meminfo: memFree=27580/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=84428 CPUtime=3.03
/proc/5370/stat : 5370 (cudf_fumax_bu-0) R 5369 5370 1745 0 -1 4202496 21013 0 0 0 292 11 0 0 20 0 1 0 115651910 86454272 19266 18446744073709551615 4194304 5895655 140734745365696 140734745360552 4452714 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/5370/statm: 21107 19266 203 416 0 20688 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 84428

[startup+6.30024 s]
/proc/loadavg: 0.98 0.98 0.99 2/65 5371
/proc/meminfo: memFree=27456/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=84428 CPUtime=6.21
/proc/5370/stat : 5370 (cudf_fumax_bu-0) R 5369 5370 1745 0 -1 4202496 21034 0 0 0 609 12 0 0 20 0 1 0 115651910 86454272 19287 18446744073709551615 4194304 5895655 140734745365696 140734745360552 4452045 0 0 16781316 16929 0 0 0 17 0 0 0 3 0 0
/proc/5370/statm: 21107 19287 203 416 0 20688 0
Current children cumulated CPU time (s) 6.21
Current children cumulated vsize (KiB) 84428

[startup+12.7002 s]
/proc/loadavg: 0.98 0.98 0.99 2/65 5371
/proc/meminfo: memFree=26712/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=85060 CPUtime=12.52
/proc/5370/stat : 5370 (cudf_fumax_bu-0) R 5369 5370 1745 0 -1 4202496 21181 0 0 0 1238 14 0 0 20 0 1 0 115651910 87101440 19434 18446744073709551615 4194304 5895655 140734745365696 140734745360552 4452590 0 0 16781316 16929 0 0 0 17 0 0 0 8 0 0
/proc/5370/statm: 21265 19434 203 416 0 20846 0
Current children cumulated CPU time (s) 12.52
Current children cumulated vsize (KiB) 85060

[startup+25.5003 s]
/proc/loadavg: 0.98 0.98 0.99 2/65 5371
/proc/meminfo: memFree=25100/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=86640 CPUtime=25.17
/proc/5370/stat : 5370 (cudf_fumax_bu-0) R 5369 5370 1745 0 -1 4202496 21541 0 0 0 2500 17 0 0 20 0 1 0 115651910 88719360 19794 18446744073709551615 4194304 5895655 140734745365696 140734745360552 5084704 0 0 16781316 16929 0 0 0 17 0 0 0 13 0 0
/proc/5370/statm: 21660 19794 203 416 0 21241 0
Current children cumulated CPU time (s) 25.17
Current children cumulated vsize (KiB) 86640

[startup+51.1002 s]
/proc/loadavg: 0.99 0.98 0.99 2/65 5371
/proc/meminfo: memFree=23860/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=87440 CPUtime=50.52
/proc/5370/stat : 5370 (cudf_fumax_bu-0) R 5369 5370 1745 0 -1 4202496 21843 0 0 0 5028 24 0 0 20 0 1 0 115651910 89538560 20096 18446744073709551615 4194304 5895655 140734745365696 140734745360552 4452538 0 0 16781316 16929 0 0 0 17 0 0 0 20 0 0
/proc/5370/statm: 21860 20096 203 416 0 21441 0
Current children cumulated CPU time (s) 50.52
Current children cumulated vsize (KiB) 87440

[startup+102.3 s]
/proc/loadavg: 0.99 0.98 0.99 2/65 5371
/proc/meminfo: memFree=20140/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=90824 CPUtime=101.12
/proc/5370/stat : 5370 (cudf_fumax_bu-0) R 5369 5370 1745 0 -1 4202496 22725 0 0 0 10077 35 0 0 20 0 1 0 115651910 93003776 20978 18446744073709551615 4194304 5895655 140734745365696 140734745360552 5093533 0 0 16781316 16929 0 0 0 17 0 0 0 42 0 0
/proc/5370/statm: 22706 20978 203 416 0 22287 0
Current children cumulated CPU time (s) 101.12
Current children cumulated vsize (KiB) 90824



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+151.8 s]
/proc/loadavg: 0.99 0.98 0.99 2/65 5371
/proc/meminfo: memFree=9724/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=104412 CPUtime=150.06
/proc/5370/stat : 5370 (cudf_fumax_bu-0) R 5369 5370 1745 0 -1 4202496 25248 0 0 0 14966 40 0 0 20 0 1 0 115651910 106917888 23500 18446744073709551615 4194304 5895655 140734745365696 140734745360552 5093846 0 0 16781316 16929 0 0 0 17 0 0 0 58 0 0
/proc/5370/statm: 26103 23500 203 416 0 25684 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 104412

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

Sending SIGKILL to process tree (bottom up)

Sending SIGKILL to -5370

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

[startup+153.5 s]
/proc/loadavg: 0.99 0.98 0.99 1/66 5372
/proc/meminfo: memFree=9592/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=104412 CPUtime=150.06
/proc/5370/stat : 5370 (cudf_fumax_bu-0) S 5369 5370 1745 0 -1 4202496 25248 0 0 0 14966 40 0 0 20 0 1 0 115651910 106917888 23500 18446744073709551615 4194304 5895655 140734745365696 140734745357736 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 58 0 0
/proc/5370/statm: 26103 23500 203 416 0 25684 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 104412

[startup+156.7 s]
/proc/loadavg: 0.91 0.97 0.98 1/66 5372
/proc/meminfo: memFree=9592/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=104412 CPUtime=150.06
/proc/5370/stat : 5370 (cudf_fumax_bu-0) S 5369 5370 1745 0 -1 4202496 25248 0 0 0 14966 40 0 0 20 0 1 0 115651910 106917888 23500 18446744073709551615 4194304 5895655 140734745365696 140734745357736 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 58 0 0
/proc/5370/statm: 26103 23500 203 416 0 25684 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 104412

[startup+159.9 s]
/proc/loadavg: 0.91 0.97 0.98 1/66 5372
/proc/meminfo: memFree=9592/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=104412 CPUtime=150.06
/proc/5370/stat : 5370 (cudf_fumax_bu-0) S 5369 5370 1745 0 -1 4202496 25248 0 0 0 14966 40 0 0 20 0 1 0 115651910 106917888 23500 18446744073709551615 4194304 5895655 140734745365696 140734745357736 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 58 0 0
/proc/5370/statm: 26103 23500 203 416 0 25684 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 104412

[startup+160.705 s]
/proc/loadavg: 0.84 0.95 0.98 1/66 5372
/proc/meminfo: memFree=9592/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=104412 CPUtime=150.06
/proc/5370/stat : 5370 (cudf_fumax_bu-0) S 5369 5370 1745 0 -1 4202496 25248 0 0 0 14966 40 0 0 20 0 1 0 115651910 106917888 23500 18446744073709551615 4194304 5895655 140734745365696 140734745357736 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 58 0 0
/proc/5370/statm: 26103 23500 203 416 0 25684 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 104412

[startup+161.5 s]
/proc/loadavg: 0.84 0.95 0.98 1/66 5372
/proc/meminfo: memFree=9592/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=104412 CPUtime=150.06
/proc/5370/stat : 5370 (cudf_fumax_bu-0) S 5369 5370 1745 0 -1 4202496 25248 0 0 0 14966 40 0 0 20 0 1 0 115651910 106917888 23500 18446744073709551615 4194304 5895655 140734745365696 140734745357736 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 58 0 0
/proc/5370/statm: 26103 23500 203 416 0 25684 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 104412

[startup+161.7 s]
/proc/loadavg: 0.84 0.95 0.98 1/66 5372
/proc/meminfo: memFree=9592/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=104412 CPUtime=150.06
/proc/5370/stat : 5370 (cudf_fumax_bu-0) S 5369 5370 1745 0 -1 4202496 25248 0 0 0 14966 40 0 0 20 0 1 0 115651910 106917888 23500 18446744073709551615 4194304 5895655 140734745365696 140734745357736 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 58 0 0
/proc/5370/statm: 26103 23500 203 416 0 25684 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 104412

[startup+161.805 s]
/proc/loadavg: 0.84 0.95 0.98 1/66 5372
/proc/meminfo: memFree=9592/1022884 swapFree=0/0
[pid=5370] ppid=5369 vsize=104412 CPUtime=150.06
/proc/5370/stat : 5370 (cudf_fumax_bu-0) S 5369 5370 1745 0 -1 4202496 25248 0 0 0 14966 40 0 0 20 0 1 0 115651910 106917888 23500 18446744073709551615 4194304 5895655 140734745365696 140734745357736 5205742 0 512 16781316 16929 0 0 0 17 0 0 0 58 0 0
/proc/5370/statm: 26103 23500 203 416 0 25684 0
Current children cumulated CPU time (s) 150.06
Current children cumulated vsize (KiB) 104412

Child ended because it received signal 9 (SIGKILL)
Real time (s): 161.825
CPU time (s): 150.089
CPU user time (s): 149.669
CPU system time (s): 0.420026
CPU usage (%): 92.7478
Max. virtual memory (cumulated for all children) (KiB): 104412

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 149.669
system time used= 0.420026
maximum resident set size= 94000
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 25248
page faults= 0
swaps= 0
block input operations= 43848
block output operations= 504
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 72
involuntary context switches= 17112

runsolver used 0.268016 second user time and 0.568035 second system time

The end