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/201108300820/aspcud-1.5/rand434.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand434.cudf /home/misc2010/tmp/201108300820/aspcud-1.5/rand434.cudf.dudf-random.result +sum(installedsize) 

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.34 1.12 1.03 4/36 5263
/proc/meminfo: memFree=916640/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2588 CPUtime=0
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 373 0 0 0 0 0 0 0 25 0 1 0 52550729 2650112 280 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/5260/statm: 647 280 234 194 0 34 0
[pid=5261] ppid=5260 vsize=2588 CPUtime=0
/proc/5261/stat : 5261 (aspcud-1.5) S 5260 5260 2160 34817 2160 4202560 118 0 0 0 0 0 0 0 25 0 1 0 52550729 2650112 134 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/5261/statm: 647 134 87 194 0 34 0
[pid=5262] ppid=5261 vsize=2588 CPUtime=0
/proc/5262/stat : 5262 (aspcud-1.5) R 5261 5260 2160 34817 2160 4202560 127 0 0 0 0 0 0 0 25 0 1 0 52550730 2650112 151 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/5262/statm: 647 151 104 194 0 34 0
[pid=5263] ppid=5262 vsize=2588 CPUtime=0
/proc/5263/stat : 5263 (aspcud-1.5) R 5262 5260 2160 34817 2160 4202560 0 0 0 0 0 0 0 0 25 0 1 0 52550730 2650112 47 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/5263/statm: 647 47 0 194 0 34 0

[startup+0.160251 s]
/proc/loadavg: 1.34 1.12 1.03 4/36 5263
/proc/meminfo: memFree=916640/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=0.01
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 584 1517 0 0 0 0 0 1 25 0 1 0 52550729 2658304 299 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.204229 s]
/proc/loadavg: 1.34 1.12 1.03 4/36 5263
/proc/meminfo: memFree=916640/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=0.01
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 584 1517 0 0 0 0 0 1 25 0 1 0 52550729 2658304 299 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.371761 s]
/proc/loadavg: 1.34 1.12 1.03 4/36 5263
/proc/meminfo: memFree=916640/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=0.01
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 584 1517 0 0 0 0 0 1 25 0 1 0 52550729 2658304 299 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.704265 s]
/proc/loadavg: 1.34 1.12 1.03 4/36 5263
/proc/meminfo: memFree=916640/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=0.01
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 584 1517 0 0 0 0 0 1 25 0 1 0 52550729 2658304 299 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.50791 s]
/proc/loadavg: 1.31 1.12 1.03 2/37 5271
/proc/meminfo: memFree=889236/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=0.01
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 584 1517 0 0 0 0 0 1 25 0 1 0 52550729 2658304 299 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 299 251 194 0 36 0
[pid=5269] ppid=5260 vsize=1928 CPUtime=0
/proc/5269/stat : 5269 (clasp) S 5260 5260 2160 34817 2160 4202496 274 0 19 0 0 0 0 0 23 0 1 0 52550730 1974272 160 1283457024 134512640 136285277 4291531008 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/5269/statm: 482 160 144 433 0 47 0
[pid=5270] ppid=5260 vsize=2588 CPUtime=0
/proc/5270/stat : 5270 (gringo) S 5260 5260 2160 34817 2160 4202496 381 0 24 0 0 0 0 0 22 0 1 0 52550730 2650112 272 1283457024 134512640 136933539 4287603728 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/5270/statm: 647 272 242 592 0 52 0
[pid=5271] ppid=5260 vsize=29916 CPUtime=1.08
/proc/5271/stat : 5271 (cudf2lp) R 5260 5260 2160 34817 2160 4202496 8084 0 16 0 100 8 0 0 25 0 1 0 52550731 30633984 6598 1283457024 134512640 135786343 4293440272 18446744073709551615 134554181 0 0 6 0 0 0 0 17 0 0 0 0
/proc/5271/statm: 7479 6598 135 311 0 7166 0
Current children cumulated CPU time (s) 1.09
Current children cumulated vsize (KiB) 37028

[startup+3.1082 s]
/proc/loadavg: 1.31 1.12 1.03 3/37 5271
/proc/meminfo: memFree=853828/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=0.01
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 584 1517 0 0 0 0 0 1 25 0 1 0 52550729 2658304 299 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 299 251 194 0 36 0
[pid=5269] ppid=5260 vsize=23552 CPUtime=0.14
/proc/5269/stat : 5269 (clasp) S 5260 5260 2160 34817 2160 4202496 6645 0 22 0 10 4 0 0 18 0 1 0 52550730 24117248 5470 1283457024 134512640 136285277 4291531008 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/5269/statm: 5888 5470 177 433 0 5453 0
[pid=5270] ppid=5260 vsize=31624 CPUtime=1.21
/proc/5270/stat : 5270 (gringo) R 5260 5260 2160 34817 2160 4202496 9887 0 24 0 120 1 0 0 18 0 1 0 52550730 32382976 6774 1283457024 134512640 136933539 4287603728 18446744073709551615 134752166 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5270/statm: 7906 6774 242 592 0 7311 0
[pid=5271] ppid=5260 vsize=26528 CPUtime=1.29
/proc/5271/stat : 5271 (cudf2lp) R 5260 5260 2160 34817 2160 4202496 8645 0 16 0 120 9 0 0 25 0 1 0 52550731 27164672 6415 1283457024 134512640 135786343 4293440272 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/5271/statm: 6632 6415 139 311 0 6319 0
Current children cumulated CPU time (s) 2.65
Current children cumulated vsize (KiB) 84300

[startup+6.30882 s]
/proc/loadavg: 1.31 1.12 1.03 2/36 5271
/proc/meminfo: memFree=725132/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=1.42
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 585 10165 0 16 0 0 130 12 18 0 1 0 52550729 2658304 299 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 299 251 194 0 36 0
[pid=5269] ppid=5260 vsize=84048 CPUtime=0.65
/proc/5269/stat : 5269 (clasp) S 5260 5260 2160 34817 2160 4202496 24004 0 22 0 55 10 0 0 18 0 1 0 52550730 86065152 20380 1283457024 134512640 136285277 4291531008 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/5269/statm: 21012 20380 177 433 0 20577 0
[pid=5270] ppid=5260 vsize=153192 CPUtime=3.8
/proc/5270/stat : 5270 (gringo) R 5260 5260 2160 34817 2160 4202496 44764 0 24 0 370 10 0 0 22 0 1 0 52550730 156868608 30663 1283457024 134512640 136933539 4287603728 18446744073709551615 135769271 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/5270/statm: 38298 30663 253 592 0 37703 0
Current children cumulated CPU time (s) 5.87
Current children cumulated vsize (KiB) 239836

[startup+12.7106 s]
/proc/loadavg: 1.26 1.11 1.03 2/35 5271
/proc/meminfo: memFree=786784/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=5.76
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 585 57579 0 40 0 0 550 26 18 0 1 0 52550729 2658304 299 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 299 251 194 0 36 0
[pid=5269] ppid=5260 vsize=126132 CPUtime=6.49
/proc/5269/stat : 5269 (clasp) R 5260 5260 2160 34817 2160 4202496 38215 0 22 0 637 12 0 0 25 0 1 0 52550730 129159168 31280 1283457024 134512640 136285277 4291531008 18446744073709551615 134642064 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/5269/statm: 31533 31280 234 433 0 31098 0
Current children cumulated CPU time (s) 12.25
Current children cumulated vsize (KiB) 128728

[startup+25.5035 s]
/proc/loadavg: 1.22 1.11 1.03 2/35 5271
/proc/meminfo: memFree=546348/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=5.76
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 585 57579 0 40 0 0 550 26 18 0 1 0 52550729 2658304 299 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 299 251 194 0 36 0
[pid=5269] ppid=5260 vsize=351568 CPUtime=19.28
/proc/5269/stat : 5269 (clasp) R 5260 5260 2160 34817 2160 4202496 94574 0 22 0 1896 32 0 0 25 0 1 0 52550730 360005632 87639 1283457024 134512640 136285277 4291531008 18446744073709551615 134650616 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/5269/statm: 87892 87639 234 433 0 87457 0
Current children cumulated CPU time (s) 25.04
Current children cumulated vsize (KiB) 354164

[startup+51.1106 s]
/proc/loadavg: 1.15 1.10 1.02 2/35 5271
/proc/meminfo: memFree=403128/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=5.76
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 585 57579 0 40 0 0 550 26 18 0 1 0 52550729 2658304 299 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 299 251 194 0 36 0
[pid=5269] ppid=5260 vsize=504988 CPUtime=44.87
/proc/5269/stat : 5269 (clasp) R 5260 5260 2160 34817 2160 4202496 132922 0 22 0 4442 45 0 0 25 0 1 0 52550730 517107712 125987 1283457024 134512640 136285277 4291531008 18446744073709551615 134734287 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/5269/statm: 126247 125987 234 433 0 125812 0
Current children cumulated CPU time (s) 50.63
Current children cumulated vsize (KiB) 507584

[startup+102.306 s]
/proc/loadavg: 1.06 1.08 1.02 2/35 5271
/proc/meminfo: memFree=4304/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=5.76
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 585 57579 0 40 0 0 550 26 18 0 1 0 52550729 2658304 299 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 299 251 194 0 36 0
[pid=5269] ppid=5260 vsize=929568 CPUtime=95.98
/proc/5269/stat : 5269 (clasp) R 5260 5260 2160 34817 2160 4202496 239067 0 22 0 9512 86 0 0 25 0 1 0 52550730 951877632 232132 1283457024 134512640 136285277 4291531008 18446744073709551615 134963435 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/5269/statm: 232392 232132 234 433 0 231957 0
Current children cumulated CPU time (s) 101.74
Current children cumulated vsize (KiB) 932164

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

[startup+103.906 s]
/proc/loadavg: 1.06 1.08 1.02 2/35 5271
/proc/meminfo: memFree=4264/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=5.76
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 585 57579 0 40 0 0 550 26 18 0 1 0 52550729 2658304 299 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 299 251 194 0 36 0
[pid=5269] ppid=5260 vsize=960408 CPUtime=97.58
/proc/5269/stat : 5269 (clasp) R 5260 5260 2160 34817 2160 4202496 246775 0 22 0 9665 93 0 0 25 0 1 0 52550730 983457792 239840 1283457024 134512640 136285277 4291531008 18446744073709551615 134642088 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/5269/statm: 240102 239840 234 433 0 239667 0
Current children cumulated CPU time (s) 103.34
Current children cumulated vsize (KiB) 963004

[startup+104.703 s]
/proc/loadavg: 1.06 1.08 1.02 2/35 5271
/proc/meminfo: memFree=4292/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=5.76
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 585 57579 0 40 0 0 550 26 18 0 1 0 52550729 2658304 299 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 299 251 194 0 36 0
[pid=5269] ppid=5260 vsize=975948 CPUtime=98.37
/proc/5269/stat : 5269 (clasp) D 5260 5260 2160 34817 2160 4202496 250649 0 22 0 9738 99 0 0 25 0 1 0 52550730 999370752 243714 1283457024 134512640 136285277 4291531008 18446744073709551615 135641886 0 0 6 18944 18446744071564410721 0 0 17 0 0 0 0
/proc/5269/statm: 243987 243714 234 433 0 243552 0
Current children cumulated CPU time (s) 104.13
Current children cumulated vsize (KiB) 978544

[startup+105.507 s]
/proc/loadavg: 1.06 1.08 1.02 1/35 5272
/proc/meminfo: memFree=985736/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=104.73
/proc/5260/stat : 5260 (aspcud-1.5) D 5259 5260 2160 34817 2160 4202496 630 310216 14 62 0 0 10331 142 18 0 1 0 52550729 2658304 143 1283457024 134512640 135304128 4291151488 18446744073709551615 134945728 0 65536 4 1132560123 18446744071564332000 0 0 17 0 0 0 0
/proc/5260/statm: 649 143 95 194 0 36 0
Current children cumulated CPU time (s) 104.73
Current children cumulated vsize (KiB) 2596

[startup+105.707 s]
/proc/loadavg: 1.06 1.08 1.02 1/35 5272
/proc/meminfo: memFree=985736/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=104.73
/proc/5260/stat : 5260 (aspcud-1.5) S 5259 5260 2160 34817 2160 4202496 711 310216 19 62 0 0 10331 142 18 0 1 0 52550729 2658304 212 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/5260/statm: 649 212 164 194 0 36 0
Current children cumulated CPU time (s) 104.73
Current children cumulated vsize (KiB) 2596

[startup+105.807 s]
/proc/loadavg: 1.06 1.08 1.02 1/35 5272
/proc/meminfo: memFree=985736/1048576 swapFree=0/0
[pid=5260] ppid=5259 vsize=2596 CPUtime=104.73
/proc/5260/stat : 5260 (aspcud-1.5) R 5259 5260 2160 34817 2160 4202496 802 310821 19 71 0 0 10331 142 19 0 1 0 52550729 2658304 230 1283457024 134512640 135304128 4291151488 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/5260/statm: 649 230 182 194 0 36 0
Current children cumulated CPU time (s) 104.73
Current children cumulated vsize (KiB) 2596

Child status: 0
Real time (s): 105.842
CPU time (s): 104.735
CPU user time (s): 103.31
CPU system time (s): 1.42409
CPU usage (%): 98.9535
Max. virtual memory (cumulated for all children) (KiB): 986480

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 103.31
system time used= 1.42409
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 313546
page faults= 92
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 7093
involuntary context switches= 7393

runsolver used 0 second user time and 0 second system time

The end