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/e381ba7e-a192-11e0-8647-00163e1e087d.cudf.log.runsolver /home/competition/cudf_fumax_bu-0.1/cudf_fumax_bu-0.1 /home/competition/data/real/e381ba7e-a192-11e0-8647-00163e1e087d.cudf /tmp/misc2012/2012-09-02-17:21/basic/cudf_fumax_bu-0.1/paranoid-size/real/e381ba7e-a192-11e0-8647-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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 0.95 0.98 0.99 2/64 5358
/proc/meminfo: memFree=138948/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=2148 CPUtime=0
/proc/5358/stat : 5358 (cudf_fumax_bu-0) D 5357 5358 1745 0 -1 4202496 246 0 0 0 0 0 0 0 20 0 1 0 115645962 2199552 168 18446744073709551615 4194304 5895655 140735498846080 140735498841992 5193680 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/5358/statm: 537 168 135 416 0 118 0

[startup+0.13178 s]
/proc/loadavg: 0.95 0.98 0.99 2/64 5358
/proc/meminfo: memFree=138948/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=8004 CPUtime=0.12
/proc/5358/stat : 5358 (cudf_fumax_bu-0) R 5357 5358 1745 0 -1 4202496 1736 0 0 0 11 1 0 0 20 0 1 0 115645962 8196096 1658 18446744073709551615 4194304 5895655 140735498846080 140735498841992 5298325 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/5358/statm: 2001 1658 149 416 0 1582 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 8004

[startup+0.200329 s]
/proc/loadavg: 0.95 0.98 0.99 2/64 5358
/proc/meminfo: memFree=138948/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=10840 CPUtime=0.19
/proc/5358/stat : 5358 (cudf_fumax_bu-0) R 5357 5358 1745 0 -1 4202496 2453 0 0 0 18 1 0 0 20 0 1 0 115645962 11100160 2375 18446744073709551615 4194304 5895655 140735498846080 140735498841992 5081931 0 0 16781316 16929 0 0 0 17 0 0 0 0 0 0
/proc/5358/statm: 2710 2375 149 416 0 2291 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 10840

[startup+0.300307 s]
/proc/loadavg: 0.95 0.98 0.99 2/64 5358
/proc/meminfo: memFree=138948/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=15328 CPUtime=0.28
/proc/5358/stat : 5358 (cudf_fumax_bu-0) R 5357 5358 1745 0 -1 4202496 3552 0 0 0 26 2 0 0 20 0 1 0 115645962 15695872 3474 18446744073709551615 4194304 5895655 140735498846080 140735498841992 4984174 0 0 16781316 16929 0 0 0 17 0 0 0 1 0 0
/proc/5358/statm: 3832 3474 149 416 0 3413 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 15328

[startup+0.700237 s]
/proc/loadavg: 0.95 0.98 0.99 2/64 5358
/proc/meminfo: memFree=138948/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=30764 CPUtime=0.66
/proc/5358/stat : 5358 (cudf_fumax_bu-0) R 5357 5358 1745 0 -1 4202496 7460 0 0 0 62 4 0 0 20 0 1 0 115645962 31502336 7333 18446744073709551615 4194304 5895655 140735498846080 140735498841992 5193680 0 0 16781316 16929 0 0 0 17 0 0 0 2 0 0
/proc/5358/statm: 7691 7333 149 416 0 7272 0
Current children cumulated CPU time (s) 0.66
Current children cumulated vsize (KiB) 30764

[startup+1.50023 s]
/proc/loadavg: 0.95 0.98 0.99 2/65 5359
/proc/meminfo: memFree=82512/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=52604 CPUtime=1.35
/proc/5358/stat : 5358 (cudf_fumax_bu-0) R 5357 5358 1745 0 -1 4202496 12993 0 0 0 126 9 0 0 20 0 1 0 115645962 53866496 12817 18446744073709551615 4194304 5895655 140735498846080 140735498839416 4269474 0 0 16781316 16929 0 0 0 17 0 0 0 12 0 0
/proc/5358/statm: 13151 12817 155 416 0 12732 0
Current children cumulated CPU time (s) 1.35
Current children cumulated vsize (KiB) 52604

[startup+3.10022 s]
/proc/loadavg: 0.95 0.98 0.99 2/65 5359
/proc/meminfo: memFree=61432/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=66636 CPUtime=2.95
/proc/5358/stat : 5358 (cudf_fumax_bu-0) R 5357 5358 1745 0 -1 4202496 15517 0 0 0 283 12 0 0 20 0 1 0 115645962 68235264 14959 18446744073709551615 4194304 5895655 140735498846080 140735498840936 4452045 0 0 16781316 16929 0 0 0 17 0 0 0 12 0 0
/proc/5358/statm: 16659 14959 195 416 0 16240 0
Current children cumulated CPU time (s) 2.95
Current children cumulated vsize (KiB) 66636

[startup+6.30022 s]
/proc/loadavg: 0.95 0.98 0.99 2/65 5359
/proc/meminfo: memFree=60440/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=68120 CPUtime=6.1
/proc/5358/stat : 5358 (cudf_fumax_bu-0) R 5357 5358 1745 0 -1 4202496 15764 0 0 0 598 12 0 0 20 0 1 0 115645962 69754880 15168 18446744073709551615 4194304 5895655 140735498846080 140735498840936 4447058 0 0 16781316 16929 0 0 0 17 0 0 0 14 0 0
/proc/5358/statm: 17030 15168 195 416 0 16611 0
Current children cumulated CPU time (s) 6.1
Current children cumulated vsize (KiB) 68120

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

[startup+6.40028 s]
/proc/loadavg: 0.95 0.98 0.99 2/65 5359
/proc/meminfo: memFree=60440/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=68120 CPUtime=6.2
/proc/5358/stat : 5358 (cudf_fumax_bu-0) R 5357 5358 1745 0 -1 4202496 15765 0 0 0 608 12 0 0 20 0 1 0 115645962 69754880 15169 18446744073709551615 4194304 5895655 140735498846080 140735498840936 4436099 0 0 16781316 16929 0 0 0 17 0 0 0 14 0 0
/proc/5358/statm: 17030 15169 195 416 0 16611 0
Current children cumulated CPU time (s) 6.2
Current children cumulated vsize (KiB) 68120

[startup+9.60021 s]
/proc/loadavg: 0.95 0.98 0.99 2/65 5359
/proc/meminfo: memFree=59944/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=68120 CPUtime=9.37
/proc/5358/stat : 5358 (cudf_fumax_bu-0) R 5357 5358 1745 0 -1 4202496 16138 0 0 0 923 14 0 0 20 0 1 0 115645962 69754880 15498 18446744073709551615 4194304 5895655 140735498846080 140735498840936 4456366 0 0 16781316 16929 0 0 0 17 0 0 0 14 0 0
/proc/5358/statm: 17030 15498 195 416 0 16611 0
Current children cumulated CPU time (s) 9.37
Current children cumulated vsize (KiB) 68120

[startup+10.4002 s]
/proc/loadavg: 0.96 0.98 0.99 2/65 5359
/proc/meminfo: memFree=59076/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=68120 CPUtime=10.15
/proc/5358/stat : 5358 (cudf_fumax_bu-0) R 5357 5358 1745 0 -1 4202496 16243 0 0 0 1000 15 0 0 20 0 1 0 115645962 69754880 15603 18446744073709551615 4194304 5895655 140735498846080 140735498840936 4455757 0 0 16781316 16929 0 0 0 17 0 0 0 16 0 0
/proc/5358/statm: 17030 15603 195 416 0 16611 0
Current children cumulated CPU time (s) 10.15
Current children cumulated vsize (KiB) 68120

[startup+11.2002 s]
/proc/loadavg: 0.96 0.98 0.99 2/65 5359
/proc/meminfo: memFree=58456/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=68120 CPUtime=10.95
/proc/5358/stat : 5358 (cudf_fumax_bu-0) R 5357 5358 1745 0 -1 4202496 16245 0 0 0 1079 16 0 0 20 0 1 0 115645962 69754880 15605 18446744073709551615 4194304 5895655 140735498846080 140735498840936 5073321 0 0 16781316 16929 0 0 0 17 0 0 0 16 0 0
/proc/5358/statm: 17030 15605 195 416 0 16611 0
Current children cumulated CPU time (s) 10.95
Current children cumulated vsize (KiB) 68120

[startup+11.6002 s]
/proc/loadavg: 0.96 0.98 0.99 2/65 5359
/proc/meminfo: memFree=58456/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=68120 CPUtime=11.34
/proc/5358/stat : 5358 (cudf_fumax_bu-0) R 5357 5358 1745 0 -1 4202496 16246 0 0 0 1118 16 0 0 20 0 1 0 115645962 69754880 15606 18446744073709551615 4194304 5895655 140735498846080 140735498840936 4473034 0 0 16781316 16929 0 0 0 17 0 0 0 16 0 0
/proc/5358/statm: 17030 15606 195 416 0 16611 0
Current children cumulated CPU time (s) 11.34
Current children cumulated vsize (KiB) 68120

[startup+11.7002 s]
/proc/loadavg: 0.96 0.98 0.99 2/65 5359
/proc/meminfo: memFree=58456/1022884 swapFree=0/0
[pid=5358] ppid=5357 vsize=68120 CPUtime=11.44
/proc/5358/stat : 5358 (cudf_fumax_bu-0) R 5357 5358 1745 0 -1 4202496 16247 0 0 0 1128 16 0 0 20 0 1 0 115645962 69754880 15607 18446744073709551615 4194304 5895655 140735498846080 140735498840936 4468975 0 0 16781316 16929 0 0 0 17 0 0 0 16 0 0
/proc/5358/statm: 17030 15607 195 416 0 16611 0
Current children cumulated CPU time (s) 11.44
Current children cumulated vsize (KiB) 68120

Child status: 0
Real time (s): 11.7715
CPU time (s): 11.5247
CPU user time (s): 11.3447
CPU system time (s): 0.180011
CPU usage (%): 97.9039
Max. virtual memory (cumulated for all children) (KiB): 68120

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 11.3447
system time used= 0.180011
maximum resident set size= 62428
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 16249
page faults= 0
swaps= 0
block input operations= 37048
block output operations= 264
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 19
involuntary context switches= 1323

runsolver used 0.012 second user time and 0.052003 second system time

The end