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/201109011757/aspcud-1.5/rand21.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand21.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/rand21.cudf.dudf-random.result -sum(pin-priority-1),-sum(pin-priority-500),-sum(pin-priority-700),-notuptodate,-removed,-changed 

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.13 0.93 0.53 5/40 23178
/proc/meminfo: memFree=842576/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2588 CPUtime=0
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 374 0 0 0 0 0 0 0 23 0 1 0 71663044 2650112 280 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/23176/statm: 647 280 234 194 0 34 0
[pid=23177] ppid=23176 vsize=2588 CPUtime=0
/proc/23177/stat : 23177 (aspcud-1.5) R 23176 23176 22717 34817 22717 4202560 110 0 0 0 0 0 0 0 25 0 1 0 71663044 2650112 133 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/23177/statm: 647 133 86 194 0 34 0
[pid=23178] ppid=23177 vsize=2588 CPUtime=0
/proc/23178/stat : 23178 (aspcud-1.5) R 23177 23176 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 71663044 2650112 47 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/23178/statm: 647 47 0 194 0 34 0

[startup+0.139466 s]
/proc/loadavg: 1.13 0.93 0.53 5/40 23178
/proc/meminfo: memFree=842576/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=0
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 1517 0 0 0 0 0 0 25 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.213839 s]
/proc/loadavg: 1.13 0.93 0.53 5/40 23178
/proc/meminfo: memFree=842576/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=0
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 1517 0 0 0 0 0 0 25 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.303872 s]
/proc/loadavg: 1.13 0.93 0.53 5/40 23178
/proc/meminfo: memFree=842576/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=0
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 1517 0 0 0 0 0 0 25 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.703474 s]
/proc/loadavg: 1.13 0.93 0.53 5/40 23178
/proc/meminfo: memFree=842576/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=0
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 1517 0 0 0 0 0 0 25 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50751 s]
/proc/loadavg: 1.13 0.93 0.53 1/42 23187
/proc/meminfo: memFree=810020/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=0
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 1517 0 0 0 0 0 0 25 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
[pid=23185] ppid=23176 vsize=1928 CPUtime=0
/proc/23185/stat : 23185 (clasp) S 23176 23176 22717 34817 22717 4202496 292 0 0 0 0 0 0 0 25 0 1 0 71663045 1974272 159 1283457024 134512640 136285277 4287490784 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/23185/statm: 482 159 144 433 0 47 0
[pid=23186] ppid=23176 vsize=2584 CPUtime=0
/proc/23186/stat : 23186 (gringo) S 23176 23176 22717 34817 22717 4202496 405 0 0 0 0 0 0 0 25 0 1 0 71663045 2646016 272 1283457024 134512640 136933539 4292206544 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/23186/statm: 646 272 242 592 0 51 0
[pid=23187] ppid=23176 vsize=29448 CPUtime=1.28
/proc/23187/stat : 23187 (cudf2lp) R 23176 23176 22717 34817 22717 4202496 8151 0 0 0 126 2 0 0 25 0 1 0 71663045 30154752 6649 1283457024 134512640 135786343 4289741040 18446744073709551615 134852499 0 0 6 0 0 0 0 17 0 0 0 0
/proc/23187/statm: 7362 6649 128 311 0 7049 0
Current children cumulated CPU time (s) 1.28
Current children cumulated vsize (KiB) 36556

[startup+3.11084 s]
/proc/loadavg: 1.13 0.93 0.53 2/42 23188
/proc/meminfo: memFree=770008/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=0
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 1517 0 0 0 0 0 0 25 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
[pid=23185] ppid=23176 vsize=11364 CPUtime=0.01
/proc/23185/stat : 23185 (clasp) S 23176 23176 22717 34817 22717 4202496 3033 0 0 0 1 0 0 0 18 0 1 0 71663045 11636736 2514 1283457024 134512640 136285277 4287490784 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/23185/statm: 2841 2514 177 433 0 2406 0
[pid=23186] ppid=23176 vsize=16120 CPUtime=0.54
/proc/23186/stat : 23186 (gringo) R 23176 23176 22717 34817 22717 4202496 4599 0 0 0 52 2 0 0 18 0 1 0 71663045 16506880 3033 1283457024 134512640 136933539 4292206544 18446744073709551615 134812304 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23186/statm: 4030 3033 242 592 0 3435 0
[pid=23187] ppid=23176 vsize=46076 CPUtime=2.24
/proc/23187/stat : 23187 (cudf2lp) R 23176 23176 22717 34817 22717 4202496 14084 0 0 0 219 5 0 0 25 0 1 0 71663045 47181824 11312 1283457024 134512640 135786343 4289741040 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/23187/statm: 11519 11312 139 311 0 11206 0
Current children cumulated CPU time (s) 2.79
Current children cumulated vsize (KiB) 76156

[startup+6.31164 s]
/proc/loadavg: 1.12 0.93 0.53 2/40 23188
/proc/meminfo: memFree=779836/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=3.66
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 29278 0 0 0 0 356 10 18 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
[pid=23185] ppid=23176 vsize=44052 CPUtime=2.32
/proc/23185/stat : 23185 (clasp) R 23176 23176 22717 34817 22717 4202496 12716 0 0 0 229 3 0 0 21 0 1 0 71663045 45109248 10782 1283457024 134512640 136285277 4287490784 18446744073709551615 134963464 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23185/statm: 11013 10782 234 433 0 10578 0
Current children cumulated CPU time (s) 5.98
Current children cumulated vsize (KiB) 46648

[startup+12.713 s]
/proc/loadavg: 1.11 0.94 0.53 2/40 23189
/proc/meminfo: memFree=698740/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=3.66
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 29278 0 0 0 0 356 10 18 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
[pid=23185] ppid=23176 vsize=117768 CPUtime=8.72
/proc/23185/stat : 23185 (clasp) R 23176 23176 22717 34817 22717 4202496 31135 0 0 0 861 11 0 0 25 0 1 0 71663045 120594432 29201 1283457024 134512640 136285277 4287490784 18446744073709551615 134963464 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23185/statm: 29442 29201 234 433 0 29007 0
Current children cumulated CPU time (s) 12.38
Current children cumulated vsize (KiB) 120364

[startup+25.5056 s]
/proc/loadavg: 1.08 0.94 0.54 2/40 23190
/proc/meminfo: memFree=604500/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=3.66
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 29278 0 0 0 0 356 10 18 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
[pid=23185] ppid=23176 vsize=212568 CPUtime=21.5
/proc/23185/stat : 23185 (clasp) R 23176 23176 22717 34817 22717 4202496 54676 0 0 0 2133 17 0 0 25 0 1 0 71663045 217669632 52742 1283457024 134512640 136285277 4287490784 18446744073709551615 134650607 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23185/statm: 53142 52742 234 433 0 52707 0
Current children cumulated CPU time (s) 25.16
Current children cumulated vsize (KiB) 215164

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

[startup+25.6056 s]
/proc/loadavg: 1.08 0.94 0.54 2/40 23190
/proc/meminfo: memFree=604500/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=3.66
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 29278 0 0 0 0 356 10 18 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
[pid=23185] ppid=23176 vsize=212568 CPUtime=21.6
/proc/23185/stat : 23185 (clasp) R 23176 23176 22717 34817 22717 4202496 54676 0 0 0 2143 17 0 0 25 0 1 0 71663045 217669632 52742 1283457024 134512640 136285277 4287490784 18446744073709551615 134967003 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23185/statm: 53142 52742 234 433 0 52707 0
Current children cumulated CPU time (s) 25.26
Current children cumulated vsize (KiB) 215164

[startup+32.0069 s]
/proc/loadavg: 1.08 0.94 0.54 2/40 23190
/proc/meminfo: memFree=613676/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=3.66
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 29278 0 0 0 0 356 10 18 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
[pid=23185] ppid=23176 vsize=202680 CPUtime=28
/proc/23185/stat : 23185 (clasp) R 23176 23176 22717 34817 22717 4202496 54679 0 0 0 2783 17 0 0 25 0 1 0 71663045 207544320 50290 1283457024 134512640 136285277 4287490784 18446744073709551615 134930720 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23185/statm: 50670 50290 234 433 0 50235 0
Current children cumulated CPU time (s) 31.66
Current children cumulated vsize (KiB) 205276

[startup+38.4099 s]
/proc/loadavg: 1.07 0.94 0.55 2/40 23191
/proc/meminfo: memFree=613800/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=3.66
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 29278 0 0 0 0 356 10 18 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
[pid=23185] ppid=23176 vsize=221000 CPUtime=34.39
/proc/23185/stat : 23185 (clasp) R 23176 23176 22717 34817 22717 4202496 59321 0 0 0 3418 21 0 0 25 0 1 0 71663045 226304000 54932 1283457024 134512640 136285277 4287490784 18446744073709551615 134985098 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23185/statm: 55250 54932 234 433 0 54815 0
Current children cumulated CPU time (s) 38.05
Current children cumulated vsize (KiB) 223596

[startup+40.0103 s]
/proc/loadavg: 1.06 0.94 0.55 2/40 23191
/proc/meminfo: memFree=584040/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=3.66
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 29278 0 0 0 0 356 10 18 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
[pid=23185] ppid=23176 vsize=234544 CPUtime=35.99
/proc/23185/stat : 23185 (clasp) R 23176 23176 22717 34817 22717 4202496 62722 0 0 0 3577 22 0 0 25 0 1 0 71663045 240173056 58333 1283457024 134512640 136285277 4287490784 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23185/statm: 58636 58333 234 433 0 58201 0
Current children cumulated CPU time (s) 39.65
Current children cumulated vsize (KiB) 237140

[startup+40.8105 s]
/proc/loadavg: 1.06 0.94 0.55 2/40 23191
/proc/meminfo: memFree=581188/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=3.66
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 29278 0 0 0 0 356 10 18 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
[pid=23185] ppid=23176 vsize=234792 CPUtime=36.79
/proc/23185/stat : 23185 (clasp) R 23176 23176 22717 34817 22717 4202496 63047 0 0 0 3657 22 0 0 25 0 1 0 71663045 240427008 58400 1283457024 134512640 136285277 4287490784 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23185/statm: 58698 58400 234 433 0 58263 0
Current children cumulated CPU time (s) 40.45
Current children cumulated vsize (KiB) 237388

[startup+41.2106 s]
/proc/loadavg: 1.06 0.94 0.55 2/40 23191
/proc/meminfo: memFree=581188/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=3.66
/proc/23176/stat : 23176 (aspcud-1.5) S 23175 23176 22717 34817 22717 4202496 582 29278 0 0 0 0 356 10 18 0 1 0 71663044 2658304 299 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23176/statm: 649 299 251 194 0 36 0
[pid=23185] ppid=23176 vsize=234792 CPUtime=37.19
/proc/23185/stat : 23185 (clasp) R 23176 23176 22717 34817 22717 4202496 63047 0 0 0 3697 22 0 0 25 0 1 0 71663045 240427008 58400 1283457024 134512640 136285277 4287490784 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23185/statm: 58698 58400 234 433 0 58263 0
Current children cumulated CPU time (s) 40.85
Current children cumulated vsize (KiB) 237388

[startup+41.6107 s]
/proc/loadavg: 1.06 0.94 0.55 2/40 23191
/proc/meminfo: memFree=581188/1048576 swapFree=0/0
[pid=23176] ppid=23175 vsize=2596 CPUtime=41.25
/proc/23176/stat : 23176 (aspcud-1.5) R 23175 23176 22717 34817 22717 4202496 719 93350 0 0 0 0 4086 39 22 0 1 0 71663044 2658304 304 1283457024 134512640 135304128 4290368880 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/23176/statm: 649 304 256 194 0 36 0
Current children cumulated CPU time (s) 41.25
Current children cumulated vsize (KiB) 2596

Child status: 0
Real time (s): 41.6241
CPU time (s): 41.2746
CPU user time (s): 40.8706
CPU system time (s): 0.404025
CPU usage (%): 99.1603
Max. virtual memory (cumulated for all children) (KiB): 238196

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 40.8706
system time used= 0.404025
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 96543
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= 1671
involuntary context switches= 1785

runsolver used 0.012 second user time and 0 second system time

The end