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/201108241238/aspcud-trendy-1.5/rand376.cudf.s-e.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e/rand376.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand376.cudf.s-e.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: 0.93 1.01 0.99 5/35 12118 /proc/meminfo: memFree=517036/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2588 CPUtime=0 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 374 0 0 0 0 0 0 0 18 0 1 0 2878957 2650112 280 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/12116/statm: 647 280 234 194 0 34 0 [pid=12117] ppid=12116 vsize=2588 CPUtime=0 /proc/12117/stat : 12117 (aspcud-trendy-1) R 12116 12116 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 2878957 2650112 133 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/12117/statm: 647 133 86 194 0 34 0 [pid=12118] ppid=12117 vsize=2588 CPUtime=0 /proc/12118/stat : 12118 (aspcud-trendy-1) R 12117 12116 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2878957 2650112 47 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/12118/statm: 647 47 0 194 0 34 0 [startup+0.114 s] /proc/loadavg: 0.93 1.01 0.99 5/35 12118 /proc/meminfo: memFree=517036/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=0 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 618 2230 0 0 0 0 0 0 25 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.204016 s] /proc/loadavg: 0.93 1.01 0.99 5/35 12118 /proc/meminfo: memFree=517036/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=0 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 618 2230 0 0 0 0 0 0 25 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.304032 s] /proc/loadavg: 0.93 1.01 0.99 5/35 12118 /proc/meminfo: memFree=517036/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=0 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 618 2230 0 0 0 0 0 0 25 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.704559 s] /proc/loadavg: 0.93 1.01 0.99 5/35 12118 /proc/meminfo: memFree=517036/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=0 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 618 2230 0 0 0 0 0 0 25 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50426 s] /proc/loadavg: 0.93 1.01 0.99 2/36 12130 /proc/meminfo: memFree=500028/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=1.36 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 619 15324 0 0 0 0 129 7 15 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 [pid=12128] ppid=12116 vsize=17492 CPUtime=0.12 /proc/12128/stat : 12128 (clasp) R 12116 12116 1511 34817 1511 4202496 4552 0 0 0 7 5 0 0 18 0 1 0 2878958 17911808 4034 1283457024 134512640 136285277 4290692560 18446744073709551615 134771290 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12128/statm: 4373 4034 188 433 0 3938 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 20088 [startup+3.1046 s] /proc/loadavg: 0.93 1.01 0.99 2/35 12130 /proc/meminfo: memFree=498308/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=1.36 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 619 15324 0 0 0 0 129 7 15 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 [pid=12128] ppid=12116 vsize=20060 CPUtime=1.72 /proc/12128/stat : 12128 (clasp) R 12116 12116 1511 34817 1511 4202496 5669 0 0 0 167 5 0 0 20 0 1 0 2878958 20541440 4787 1283457024 134512640 136285277 4290692560 18446744073709551615 134963475 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12128/statm: 5015 4787 234 433 0 4580 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 22656 [startup+6.30539 s] /proc/loadavg: 0.93 1.01 0.99 2/35 12130 /proc/meminfo: memFree=490760/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=1.36 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 619 15324 0 0 0 0 129 7 15 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 [pid=12128] ppid=12116 vsize=28120 CPUtime=4.92 /proc/12128/stat : 12128 (clasp) R 12116 12116 1511 34817 1511 4202496 7680 0 0 0 487 5 0 0 25 0 1 0 2878958 28794880 6798 1283457024 134512640 136285277 4290692560 18446744073709551615 134735664 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12128/statm: 7030 6798 234 433 0 6595 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 30716 [startup+12.7069 s] /proc/loadavg: 0.94 1.00 0.99 2/35 12130 /proc/meminfo: memFree=484188/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=1.36 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 619 15324 0 0 0 0 129 7 15 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 [pid=12128] ppid=12116 vsize=34720 CPUtime=11.32 /proc/12128/stat : 12128 (clasp) R 12116 12116 1511 34817 1511 4202496 9322 0 0 0 1127 5 0 0 25 0 1 0 2878958 35553280 8440 1283457024 134512640 136285277 4290692560 18446744073709551615 134959560 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12128/statm: 8680 8440 234 433 0 8245 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 37316 [startup+25.5092 s] /proc/loadavg: 0.95 1.00 0.99 2/35 12130 /proc/meminfo: memFree=460504/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=1.36 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 619 15324 0 0 0 0 129 7 15 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 [pid=12128] ppid=12116 vsize=58192 CPUtime=24.11 /proc/12128/stat : 12128 (clasp) R 12116 12116 1511 34817 1511 4202496 15208 0 0 0 2405 6 0 0 25 0 1 0 2878958 59588608 14326 1283457024 134512640 136285277 4290692560 18446744073709551615 134651228 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12128/statm: 14548 14326 234 433 0 14113 0 Current children cumulated CPU time (s) 25.47 Current children cumulated vsize (KiB) 60788 [startup+51.1044 s] /proc/loadavg: 0.97 1.00 0.99 2/35 12130 /proc/meminfo: memFree=414376/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=1.36 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 619 15324 0 0 0 0 129 7 15 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 [pid=12128] ppid=12116 vsize=104340 CPUtime=49.7 /proc/12128/stat : 12128 (clasp) R 12116 12116 1511 34817 1511 4202496 26728 0 0 0 4956 14 0 0 25 0 1 0 2878958 106844160 25846 1283457024 134512640 136285277 4290692560 18446744073709551615 134959967 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12128/statm: 26085 25846 234 433 0 25650 0 Current children cumulated CPU time (s) 51.06 Current children cumulated vsize (KiB) 106936 [startup+102.313 s] /proc/loadavg: 0.98 1.00 0.99 2/35 12130 /proc/meminfo: memFree=382260/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=1.36 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 619 15324 0 0 0 0 129 7 15 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 [pid=12128] ppid=12116 vsize=136420 CPUtime=100.9 /proc/12128/stat : 12128 (clasp) R 12116 12116 1511 34817 1511 4202496 34741 0 0 0 10073 17 0 0 25 0 1 0 2878958 139694080 33859 1283457024 134512640 136285277 4290692560 18446744073709551615 134966710 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12128/statm: 34105 33859 234 433 0 33670 0 Current children cumulated CPU time (s) 102.26 Current children cumulated vsize (KiB) 139016 [startup+162.308 s] /proc/loadavg: 0.99 1.00 0.99 2/37 12133 /proc/meminfo: memFree=380624/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=1.36 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 619 15324 0 0 0 0 129 7 15 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 [pid=12128] ppid=12116 vsize=137872 CPUtime=160.88 /proc/12128/stat : 12128 (clasp) R 12116 12116 1511 34817 1511 4202496 35100 0 0 0 16071 17 0 0 25 0 1 0 2878958 141180928 34218 1283457024 134512640 136285277 4290692560 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12128/statm: 34468 34218 234 433 0 34033 0 Current children cumulated CPU time (s) 162.24 Current children cumulated vsize (KiB) 140468 [startup+222.312 s] /proc/loadavg: 0.99 1.00 0.99 2/37 12139 /proc/meminfo: memFree=380004/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=1.36 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 619 15324 0 0 0 0 129 7 15 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 [pid=12128] ppid=12116 vsize=138532 CPUtime=220.82 /proc/12128/stat : 12128 (clasp) R 12116 12116 1511 34817 1511 4202496 35247 0 0 0 22063 19 0 0 25 0 1 0 2878958 141856768 34365 1283457024 134512640 136285277 4290692560 18446744073709551615 134723341 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12128/statm: 34633 34365 234 433 0 34198 0 Current children cumulated CPU time (s) 222.18 Current children cumulated vsize (KiB) 141128 [startup+282.307 s] /proc/loadavg: 0.99 1.00 0.99 2/36 12141 /proc/meminfo: memFree=379896/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=1.36 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 619 15324 0 0 0 0 129 7 15 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 [pid=12128] ppid=12116 vsize=137976 CPUtime=280.74 /proc/12128/stat : 12128 (clasp) R 12116 12116 1511 34817 1511 4202496 35397 0 0 0 28053 21 0 0 25 0 1 0 2878958 141287424 34258 1283457024 134512640 136285277 4290692560 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12128/statm: 34494 34258 234 433 0 34059 0 Current children cumulated CPU time (s) 282.1 Current children cumulated vsize (KiB) 140572 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.209 s] /proc/loadavg: 0.99 1.00 0.99 2/36 12141 /proc/meminfo: memFree=379524/1048576 swapFree=0/0 [pid=12116] ppid=12115 vsize=2596 CPUtime=1.36 /proc/12116/stat : 12116 (aspcud-trendy-1) S 12115 12116 1511 34817 1511 4202496 619 15324 0 0 0 0 129 7 15 0 1 0 2878957 2658304 299 1283457024 134512640 135304128 4293390512 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/12116/statm: 649 299 251 194 0 36 0 [pid=12128] ppid=12116 vsize=139032 CPUtime=288.64 /proc/12128/stat : 12128 (clasp) R 12116 12116 1511 34817 1511 4202496 35655 0 0 0 28843 21 0 0 25 0 1 0 2878958 142368768 34516 1283457024 134512640 136285277 4290692560 18446744073709551615 134931519 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/12128/statm: 34758 34516 234 433 0 34323 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 141628 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples Child status: 0 Real time (s): 290.24 CPU time (s): 290.054 CPU user time (s): 289.734 CPU system time (s): 0.32002 CPU usage (%): 99.9359 Max. virtual memory (cumulated for all children) (KiB): 141656 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.734 system time used= 0.32002 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 55243 page faults= 0 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 1090 involuntary context switches= 4554 runsolver used 0.008 second user time and 0 second system time The end