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/aspuncud-user-1.0/rand692.cudf.dudf-random.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-random//rand692.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/rand692.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.01 1.06 1.02 2/34 9501
/proc/meminfo: memFree=947552/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=3020 CPUtime=0
/proc/9501/stat : 9501 (runsolver) D 9500 9501 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 54744737 3092480 94 1283457024 134512640 134586868 4287517232 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/9501/statm: 755 94 62 19 0 54 0

[startup+0.153754 s]
/proc/loadavg: 1.01 1.06 1.02 2/34 9501
/proc/meminfo: memFree=947552/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=0
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+0.205797 s]
/proc/loadavg: 1.01 1.06 1.02 2/34 9501
/proc/meminfo: memFree=947552/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=0
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+0.305744 s]
/proc/loadavg: 1.01 1.06 1.02 2/34 9501
/proc/meminfo: memFree=947552/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=0
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+0.703287 s]
/proc/loadavg: 1.01 1.06 1.02 2/34 9501
/proc/meminfo: memFree=947552/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=0
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2588

[startup+1.5034 s]
/proc/loadavg: 1.01 1.06 1.02 2/38 9512
/proc/meminfo: memFree=929872/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=0
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
[pid=9510] ppid=9501 vsize=3440 CPUtime=0
/proc/9510/stat : 9510 (unclasp) S 9501 9501 2160 34817 2160 4202496 402 0 5 0 0 0 0 0 25 0 1 0 54744747 3522560 271 1283457024 134512640 135121179 4292381712 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9510/statm: 860 271 240 149 0 51 0
[pid=9511] ppid=9501 vsize=2692 CPUtime=0.01
/proc/9511/stat : 9511 (gringo) S 9501 9501 2160 34817 2160 4202496 386 0 23 0 0 1 0 0 24 0 1 0 54744747 2756608 281 1283457024 134512640 137056543 4287255280 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9511/statm: 673 281 252 622 0 48 0
[pid=9512] ppid=9501 vsize=26520 CPUtime=1.21
/proc/9512/stat : 9512 (cudf2lp) R 9501 9501 2160 34817 2160 4202496 8634 0 15 0 117 4 0 0 25 0 1 0 54744747 27156480 6409 1283457024 134512640 135786343 4292382496 18446744073709551615 134557381 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9512/statm: 6630 6409 135 311 0 6317 0
Current children cumulated CPU time (s) 1.22
Current children cumulated vsize (KiB) 35240

[startup+3.10377 s]
/proc/loadavg: 1.01 1.06 1.02 3/38 9512
/proc/meminfo: memFree=896640/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=0
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 1519 0 3 0 0 0 0 25 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
[pid=9510] ppid=9501 vsize=25068 CPUtime=0.12
/proc/9510/stat : 9510 (unclasp) S 9501 9501 2160 34817 2160 4202496 6798 0 6 0 12 0 0 0 18 0 1 0 54744747 25669632 5604 1283457024 134512640 135121179 4292381712 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/9510/statm: 6267 5604 275 149 0 5458 0
[pid=9511] ppid=9501 vsize=31912 CPUtime=1.13
/proc/9511/stat : 9511 (gringo) R 9501 9501 2160 34817 2160 4202496 9968 0 23 0 109 4 0 0 18 0 1 0 54744747 32677888 6859 1283457024 134512640 137056543 4287255280 18446744073709551615 136301936 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9511/statm: 7978 6859 253 622 0 7353 0
[pid=9512] ppid=9501 vsize=26524 CPUtime=1.56
/proc/9512/stat : 9512 (cudf2lp) R 9501 9501 2160 34817 2160 4202496 8639 0 15 0 152 4 0 0 25 0 1 0 54744747 27160576 6414 1283457024 134512640 135786343 4292382496 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/9512/statm: 6631 6414 139 311 0 6318 0
Current children cumulated CPU time (s) 2.81
Current children cumulated vsize (KiB) 86092

[startup+6.31468 s]
/proc/loadavg: 1.01 1.06 1.02 2/36 9512
/proc/meminfo: memFree=882296/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=4.15
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 37575 0 41 0 0 396 19 18 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
[pid=9510] ppid=9501 vsize=66840 CPUtime=1.88
/proc/9510/stat : 9510 (unclasp) R 9501 9501 2160 34817 2160 4202496 32057 0 7 0 176 12 0 0 20 0 1 0 54744747 68444160 15313 1283457024 134512640 135121179 4292381712 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9510/statm: 16710 15313 319 149 0 15901 0
Current children cumulated CPU time (s) 6.03
Current children cumulated vsize (KiB) 69428

[startup+12.7071 s]
/proc/loadavg: 1.00 1.06 1.02 2/36 9512
/proc/meminfo: memFree=882420/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=4.15
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 37575 0 41 0 0 396 19 18 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
[pid=9510] ppid=9501 vsize=65936 CPUtime=8.26
/proc/9510/stat : 9510 (unclasp) R 9501 9501 2160 34817 2160 4202496 120518 0 7 0 778 48 0 0 25 0 1 0 54744747 67518464 15121 1283457024 134512640 135121179 4292381712 18446744073709551615 4159157317 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9510/statm: 16484 15121 319 149 0 15675 0
Current children cumulated CPU time (s) 12.41
Current children cumulated vsize (KiB) 68524

[startup+25.5054 s]
/proc/loadavg: 1.00 1.06 1.02 2/35 9512
/proc/meminfo: memFree=883296/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=4.15
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 37575 0 41 0 0 396 19 18 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
[pid=9510] ppid=9501 vsize=65576 CPUtime=21.01
/proc/9510/stat : 9510 (unclasp) R 9501 9501 2160 34817 2160 4202496 291122 0 7 0 1977 124 0 0 25 0 1 0 54744747 67149824 15072 1283457024 134512640 135121179 4292381712 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9510/statm: 16394 15072 321 149 0 15585 0
Current children cumulated CPU time (s) 25.16
Current children cumulated vsize (KiB) 68164

[startup+51.1148 s]
/proc/loadavg: 1.00 1.05 1.02 2/35 9512
/proc/meminfo: memFree=882924/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=4.15
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 37575 0 41 0 0 396 19 18 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
[pid=9510] ppid=9501 vsize=65940 CPUtime=46.6
/proc/9510/stat : 9510 (unclasp) R 9501 9501 2160 34817 2160 4202496 637177 0 7 0 4390 270 0 0 25 0 1 0 54744747 67522560 15143 1283457024 134512640 135121179 4292381712 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9510/statm: 16485 15143 321 149 0 15676 0
Current children cumulated CPU time (s) 50.75
Current children cumulated vsize (KiB) 68528

[startup+102.314 s]
/proc/loadavg: 1.00 1.04 1.01 2/35 9512
/proc/meminfo: memFree=883172/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=4.15
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 37575 0 41 0 0 396 19 18 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
[pid=9510] ppid=9501 vsize=65848 CPUtime=97.75
/proc/9510/stat : 9510 (unclasp) R 9501 9501 2160 34817 2160 4202496 1303587 0 7 0 9191 584 0 0 25 0 1 0 54744747 67428352 15114 1283457024 134512640 135121179 4292381712 18446744073709551615 134891769 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9510/statm: 16462 15114 321 149 0 15653 0
Current children cumulated CPU time (s) 101.9
Current children cumulated vsize (KiB) 68436

[startup+162.305 s]
/proc/loadavg: 1.00 1.03 1.01 2/35 9512
/proc/meminfo: memFree=882304/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=4.15
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 37575 0 41 0 0 396 19 18 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
[pid=9510] ppid=9501 vsize=66220 CPUtime=157.69
/proc/9510/stat : 9510 (unclasp) R 9501 9501 2160 34817 2160 4202496 2057253 0 7 0 14874 895 0 0 25 0 1 0 54744747 67809280 15263 1283457024 134512640 135121179 4292381712 18446744073709551615 134891399 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9510/statm: 16555 15263 321 149 0 15746 0
Current children cumulated CPU time (s) 161.84
Current children cumulated vsize (KiB) 68808

[startup+222.308 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 9512
/proc/meminfo: memFree=881932/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=4.15
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 37575 0 41 0 0 396 19 18 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
[pid=9510] ppid=9501 vsize=67632 CPUtime=217.63
/proc/9510/stat : 9510 (unclasp) R 9501 9501 2160 34817 2160 4202496 2809387 0 7 0 20515 1248 0 0 25 0 1 0 54744747 69255168 15622 1283457024 134512640 135121179 4292381712 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9510/statm: 16908 15622 321 149 0 16099 0
Current children cumulated CPU time (s) 221.78
Current children cumulated vsize (KiB) 70220

[startup+282.307 s]
/proc/loadavg: 1.00 1.02 1.00 2/37 9516
/proc/meminfo: memFree=881784/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=4.15
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 37575 0 41 0 0 396 19 18 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
[pid=9510] ppid=9501 vsize=66360 CPUtime=277.59
/proc/9510/stat : 9510 (unclasp) R 9501 9501 2160 34817 2160 4202496 3614894 0 7 0 26187 1572 0 0 25 0 1 0 54744747 67952640 15331 1283457024 134512640 135121179 4292381712 18446744073709551615 134713325 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9510/statm: 16590 15331 321 149 0 15781 0
Current children cumulated CPU time (s) 281.74
Current children cumulated vsize (KiB) 68948



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.61 s]
/proc/loadavg: 1.00 1.02 1.00 2/37 9517
/proc/meminfo: memFree=881660/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=4.15
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 37575 0 41 0 0 396 19 18 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
[pid=9510] ppid=9501 vsize=66360 CPUtime=285.89
/proc/9510/stat : 9510 (unclasp) R 9501 9501 2160 34817 2160 4202496 3723857 0 7 0 26964 1625 0 0 25 0 1 0 54744747 67952640 15334 1283457024 134512640 135121179 4292381712 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9510/statm: 16590 15334 321 149 0 15781 0
Current children cumulated CPU time (s) 290.04
Current children cumulated vsize (KiB) 68948

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

[startup+290.61 s]
/proc/loadavg: 1.00 1.02 1.00 2/37 9517
/proc/meminfo: memFree=881660/1048576 swapFree=0/0
[pid=9501] ppid=9500 vsize=2588 CPUtime=4.15
/proc/9501/stat : 9501 (aspuncud-user-1) S 9500 9501 2160 34817 2160 4202496 572 37575 0 41 0 0 396 19 18 0 1 0 54744737 2650112 297 1283457024 134512640 135304128 4293736656 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/9501/statm: 647 297 251 194 0 34 0
[pid=9510] ppid=9501 vsize=66360 CPUtime=285.89
/proc/9510/stat : 9510 (unclasp) R 9501 9501 2160 34817 2160 4202496 3723857 0 7 0 26964 1625 0 0 25 0 1 0 54744747 67952640 15334 1283457024 134512640 135121179 4292381712 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/9510/statm: 16590 15334 321 149 0 15781 0
Current children cumulated CPU time (s) 290.04
Current children cumulated vsize (KiB) 68948

Child status: 0
Real time (s): 290.653
CPU time (s): 290.066
CPU user time (s): 273.613
CPU system time (s): 16.453
CPU usage (%): 99.7982
Max. virtual memory (cumulated for all children) (KiB): 150536

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 273.613
system time used= 16.453
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 3764394
page faults= 50
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 4314
involuntary context switches= 6847

runsolver used 0 second user time and 0.004 second system time

The end