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: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand6b4d6e.cudf.impossible.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/impossible//rand6b4d6e.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand6b4d6e.cudf.impossible.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 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: 1.11 1.06 1.01 2/40 16916
/proc/meminfo: memFree=723980/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=3028 CPUtime=0
/proc/16916/stat : 16916 (runsolver) D 16915 16916 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 24 0 1 0 880675124 3100672 94 1283457024 134512640 134586868 4289303536 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/16916/statm: 757 94 62 19 0 55 0

[startup+0.149289 s]
/proc/loadavg: 1.11 1.06 1.01 2/40 16916
/proc/meminfo: memFree=723980/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=0
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 2210 0 3 0 0 0 0 25 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.205332 s]
/proc/loadavg: 1.11 1.06 1.01 2/40 16916
/proc/meminfo: memFree=723980/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=0
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 2210 0 3 0 0 0 0 25 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.305299 s]
/proc/loadavg: 1.11 1.06 1.01 2/40 16916
/proc/meminfo: memFree=723980/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=0
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 2210 0 3 0 0 0 0 25 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.711471 s]
/proc/loadavg: 1.11 1.06 1.01 2/40 16916
/proc/meminfo: memFree=723980/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=0
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 2210 0 3 0 0 0 0 25 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.51161 s]
/proc/loadavg: 1.11 1.06 1.01 2/44 16930
/proc/meminfo: memFree=686040/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=0
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 2210 0 3 0 0 0 0 25 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
[pid=16928] ppid=16916 vsize=1872 CPUtime=0
/proc/16928/stat : 16928 (clasp) S 16916 16916 4159 34819 4229 4202496 270 0 15 0 0 0 0 0 23 0 1 0 880675129 1916928 153 1283457024 134512640 136223643 4290626096 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/16928/statm: 468 153 138 418 0 48 0
[pid=16929] ppid=16916 vsize=2612 CPUtime=0
/proc/16929/stat : 16929 (gringo) S 16916 16916 4159 34819 4229 4202496 386 0 22 0 0 0 0 0 23 0 1 0 880675129 2674688 277 1283457024 134512640 136959103 4293415776 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/16929/statm: 653 277 247 598 0 52 0
[pid=16930] ppid=16916 vsize=48896 CPUtime=1.25
/proc/16930/stat : 16930 (cudf2lp) R 16916 16916 4159 34819 4229 4202496 13577 0 14 0 120 5 0 0 25 0 1 0 880675129 50069504 11438 1283457024 134512640 135749571 4290632752 18446744073709551615 135187674 0 0 6 0 0 0 0 17 0 0 0 0
/proc/16930/statm: 12224 11438 127 302 0 11920 0
Current children cumulated CPU time (s) 1.25
Current children cumulated vsize (KiB) 55976

[startup+3.10212 s]
/proc/loadavg: 1.11 1.06 1.01 3/44 16930
/proc/meminfo: memFree=651884/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=0
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 2210 0 3 0 0 0 0 25 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
[pid=16928] ppid=16916 vsize=17804 CPUtime=0.09
/proc/16928/stat : 16928 (clasp) S 16916 16916 4159 34819 4229 4202496 4865 0 18 0 9 0 0 0 18 0 1 0 880675129 18231296 4093 1283457024 134512640 136223643 4290626096 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/16928/statm: 4451 4093 174 418 0 4031 0
[pid=16929] ppid=16916 vsize=25664 CPUtime=0.79
/proc/16929/stat : 16929 (gringo) R 16916 16916 4159 34819 4229 4202496 7892 0 22 0 78 1 0 0 18 0 1 0 880675129 26279936 4618 1283457024 134512640 136959103 4293415776 18446744073709551615 136161119 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16929/statm: 6416 4618 247 598 0 5815 0
[pid=16930] ppid=16916 vsize=62344 CPUtime=1.95
/proc/16930/stat : 16930 (cudf2lp) R 16916 16916 4159 34819 4229 4202496 18987 0 14 0 187 8 0 0 25 0 1 0 880675129 63840256 15186 1283457024 134512640 135749571 4290632752 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0
/proc/16930/statm: 15586 15186 129 302 0 15282 0
Current children cumulated CPU time (s) 2.83
Current children cumulated vsize (KiB) 108408

[startup+6.30774 s]
/proc/loadavg: 1.18 1.07 1.01 2/42 16930
/proc/meminfo: memFree=667048/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=4.73
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 44746 0 40 0 0 455 18 18 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
[pid=16928] ppid=16916 vsize=70088 CPUtime=1.29
/proc/16928/stat : 16928 (clasp) R 16916 16916 4159 34819 4229 4202496 20302 0 19 0 125 4 0 0 18 0 1 0 880675129 71770112 16177 1283457024 134512640 136223643 4290626096 18446744073709551615 134873941 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16928/statm: 17522 16177 214 418 0 17102 0
Current children cumulated CPU time (s) 6.02
Current children cumulated vsize (KiB) 72684

[startup+12.7099 s]
/proc/loadavg: 1.17 1.07 1.01 2/42 16930
/proc/meminfo: memFree=655152/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=4.73
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 44746 0 40 0 0 455 18 18 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
[pid=16928] ppid=16916 vsize=68872 CPUtime=7.7
/proc/16928/stat : 16928 (clasp) R 16916 16916 4159 34819 4229 4202496 20345 0 19 0 766 4 0 0 25 0 1 0 880675129 70524928 15959 1283457024 134512640 136223643 4290626096 18446744073709551615 134664705 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16928/statm: 17218 15959 225 418 0 16798 0
Current children cumulated CPU time (s) 12.43
Current children cumulated vsize (KiB) 71468

[startup+25.5131 s]
/proc/loadavg: 1.13 1.07 1.01 2/42 16930
/proc/meminfo: memFree=655152/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=4.73
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 44746 0 40 0 0 455 18 18 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
[pid=16928] ppid=16916 vsize=68872 CPUtime=20.5
/proc/16928/stat : 16928 (clasp) R 16916 16916 4159 34819 4229 4202496 20345 0 19 0 2046 4 0 0 25 0 1 0 880675129 70524928 15959 1283457024 134512640 136223643 4290626096 18446744073709551615 134931000 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16928/statm: 17218 15959 225 418 0 16798 0
Current children cumulated CPU time (s) 25.23
Current children cumulated vsize (KiB) 71468

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

[startup+25.6031 s]
/proc/loadavg: 1.13 1.07 1.01 2/42 16930
/proc/meminfo: memFree=655152/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=4.73
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 44746 0 40 0 0 455 18 18 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
[pid=16928] ppid=16916 vsize=68872 CPUtime=20.59
/proc/16928/stat : 16928 (clasp) R 16916 16916 4159 34819 4229 4202496 20345 0 19 0 2055 4 0 0 25 0 1 0 880675129 70524928 15959 1283457024 134512640 136223643 4290626096 18446744073709551615 134603302 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16928/statm: 17218 15959 225 418 0 16798 0
Current children cumulated CPU time (s) 25.32
Current children cumulated vsize (KiB) 71468

[startup+38.4085 s]
/proc/loadavg: 1.11 1.07 1.01 2/42 16930
/proc/meminfo: memFree=652300/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=4.73
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 44746 0 40 0 0 455 18 18 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
[pid=16928] ppid=16916 vsize=74796 CPUtime=33.37
/proc/16928/stat : 16928 (clasp) R 16916 16916 4159 34819 4229 4202496 21813 0 19 0 3333 4 0 0 25 0 1 0 880675129 76591104 17427 1283457024 134512640 136223643 4290626096 18446744073709551615 134630075 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16928/statm: 18699 17427 225 418 0 18279 0
Current children cumulated CPU time (s) 38.1
Current children cumulated vsize (KiB) 77392

[startup+44.8101 s]
/proc/loadavg: 1.10 1.06 1.01 2/42 16930
/proc/meminfo: memFree=637544/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=4.73
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 44746 0 40 0 0 455 18 18 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
[pid=16928] ppid=16916 vsize=87056 CPUtime=39.75
/proc/16928/stat : 16928 (clasp) R 16916 16916 4159 34819 4229 4202496 24844 0 19 0 3969 6 0 0 25 0 1 0 880675129 89145344 20458 1283457024 134512640 136223643 4290626096 18446744073709551615 134929407 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16928/statm: 21764 20458 225 418 0 21344 0
Current children cumulated CPU time (s) 44.48
Current children cumulated vsize (KiB) 89652

[startup+48.0108 s]
/proc/loadavg: 1.09 1.06 1.01 2/42 16930
/proc/meminfo: memFree=637544/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=4.73
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 44746 0 40 0 0 455 18 18 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
[pid=16928] ppid=16916 vsize=87056 CPUtime=42.95
/proc/16928/stat : 16928 (clasp) R 16916 16916 4159 34819 4229 4202496 24844 0 19 0 4289 6 0 0 25 0 1 0 880675129 89145344 20458 1283457024 134512640 136223643 4290626096 18446744073709551615 134924357 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16928/statm: 21764 20458 225 418 0 21344 0
Current children cumulated CPU time (s) 47.68
Current children cumulated vsize (KiB) 89652

[startup+49.6113 s]
/proc/loadavg: 1.08 1.06 1.01 2/42 16930
/proc/meminfo: memFree=637544/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=4.73
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 44746 0 40 0 0 455 18 18 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
[pid=16928] ppid=16916 vsize=87056 CPUtime=44.55
/proc/16928/stat : 16928 (clasp) R 16916 16916 4159 34819 4229 4202496 24844 0 19 0 4449 6 0 0 25 0 1 0 880675129 89145344 20458 1283457024 134512640 136223643 4290626096 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16928/statm: 21764 20458 225 418 0 21344 0
Current children cumulated CPU time (s) 49.28
Current children cumulated vsize (KiB) 89652

[startup+50.4116 s]
/proc/loadavg: 1.08 1.06 1.01 2/42 16930
/proc/meminfo: memFree=637544/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=4.73
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 44746 0 40 0 0 455 18 18 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
[pid=16928] ppid=16916 vsize=87056 CPUtime=45.35
/proc/16928/stat : 16928 (clasp) R 16916 16916 4159 34819 4229 4202496 24844 0 19 0 4529 6 0 0 25 0 1 0 880675129 89145344 20458 1283457024 134512640 136223643 4290626096 18446744073709551615 134711220 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16928/statm: 21764 20458 225 418 0 21344 0
Current children cumulated CPU time (s) 50.08
Current children cumulated vsize (KiB) 89652

[startup+50.8117 s]
/proc/loadavg: 1.08 1.06 1.01 2/42 16930
/proc/meminfo: memFree=637544/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=4.73
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 620 44746 0 40 0 0 455 18 18 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
[pid=16928] ppid=16916 vsize=87056 CPUtime=45.75
/proc/16928/stat : 16928 (clasp) R 16916 16916 4159 34819 4229 4202496 24844 0 19 0 4569 6 0 0 25 0 1 0 880675129 89145344 20458 1283457024 134512640 136223643 4290626096 18446744073709551615 134928869 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/16928/statm: 21764 20458 225 418 0 21344 0
Current children cumulated CPU time (s) 50.48
Current children cumulated vsize (KiB) 89652

[startup+50.9701 s]
/proc/loadavg: 1.08 1.06 1.01 2/42 16930
/proc/meminfo: memFree=637544/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2596 CPUtime=50.67
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 638 69598 0 59 0 0 5041 26 19 0 1 0 880675124 2658304 300 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 649 300 253 194 0 35 0
Current children cumulated CPU time (s) 50.67
Current children cumulated vsize (KiB) 2596

[startup+51.0062 s]
/proc/loadavg: 1.08 1.06 1.01 2/42 16930
/proc/meminfo: memFree=637544/1048576 swapFree=2080268/2097144
[pid=16916] ppid=16915 vsize=2700 CPUtime=50.67
/proc/16916/stat : 16916 (aspcud-trendy-1) S 16915 16916 4159 34819 4229 4202496 867 71605 0 62 0 0 5041 26 25 0 1 0 880675124 2764800 327 1283457024 134512640 135304128 4287378160 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/16916/statm: 675 327 258 194 0 61 0
Current children cumulated CPU time (s) 50.67
Current children cumulated vsize (KiB) 2700

Child status: 0
Real time (s): 51.0325
CPU time (s): 50.6872
CPU user time (s): 50.4192
CPU system time (s): 0.268016
CPU usage (%): 99.3232
Max. virtual memory (cumulated for all children) (KiB): 129900

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 50.4192
system time used= 0.268016
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 73849
page faults= 64
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 4094
involuntary context switches= 3834

runsolver used 0 second user time and 0 second system time

The end