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/e381ba7e-a192-11e0-8647-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/dudf-real//e381ba7e-a192-11e0-8647-00163e1e087d.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/e381ba7e-a192-11e0-8647-00163e1e087d.cudf.dudf-real.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.63 1.31 1.16 5/37 1077
/proc/meminfo: memFree=264888/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2584 CPUtime=0
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 5142204 2646016 279 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/1074/statm: 646 279 234 194 0 33 0
[pid=1076] ppid=1074 vsize=2584 CPUtime=0
/proc/1076/stat : 1076 (aspcud-trendy-1) R 1074 1074 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 5142204 2646016 132 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/1076/statm: 646 132 86 194 0 33 0
[pid=1077] ppid=1076 vsize=2584 CPUtime=0
/proc/1077/stat : 1077 (aspcud-trendy-1) R 1076 1074 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 5142204 2646016 46 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/1077/statm: 646 46 0 194 0 33 0

[startup+0.155594 s]
/proc/loadavg: 1.63 1.31 1.16 5/37 1077
/proc/meminfo: memFree=264888/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=0.01
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 623 2228 0 0 0 0 0 1 25 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.205602 s]
/proc/loadavg: 1.63 1.31 1.16 5/37 1077
/proc/meminfo: memFree=264888/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=0.01
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 623 2228 0 0 0 0 0 1 25 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.305638 s]
/proc/loadavg: 1.63 1.31 1.16 5/37 1077
/proc/meminfo: memFree=264888/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=0.01
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 623 2228 0 0 0 0 0 1 25 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.705709 s]
/proc/loadavg: 1.63 1.31 1.16 5/37 1077
/proc/meminfo: memFree=264888/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=0.01
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 623 2228 0 0 0 0 0 1 25 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.5059 s]
/proc/loadavg: 1.63 1.31 1.16 2/39 1089
/proc/meminfo: memFree=243276/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=0.01
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 623 2228 0 0 0 0 0 1 25 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
[pid=1087] ppid=1074 vsize=1928 CPUtime=0
/proc/1087/stat : 1087 (clasp) S 1074 1074 1511 34817 1511 4202496 291 0 0 0 0 0 0 0 25 0 1 0 5142205 1974272 159 1283457024 134512640 136285277 4288891936 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/1087/statm: 482 159 144 433 0 47 0
[pid=1088] ppid=1074 vsize=2580 CPUtime=0
/proc/1088/stat : 1088 (gringo) S 1074 1074 1511 34817 1511 4202496 403 0 0 0 0 0 0 0 25 0 1 0 5142205 2641920 271 1283457024 134512640 136933539 4291280608 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/1088/statm: 645 271 242 592 0 50 0
[pid=1089] ppid=1074 vsize=35360 CPUtime=1.49
/proc/1089/stat : 1089 (cudf2lp) R 1074 1074 1511 34817 1511 4202496 11331 0 0 0 141 8 0 0 25 0 1 0 5142205 36208640 8634 1283457024 134512640 135786343 4293288160 18446744073709551615 135199797 0 0 6 0 0 0 0 17 0 0 0 0
/proc/1089/statm: 8840 8634 134 311 0 8527 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 42460

[startup+3.10625 s]
/proc/loadavg: 1.58 1.31 1.16 3/38 1089
/proc/meminfo: memFree=236844/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=2.26
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 624 20796 0 0 1 0 211 14 15 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
[pid=1087] ppid=1074 vsize=21900 CPUtime=0.83
/proc/1087/stat : 1087 (clasp) R 1074 1074 1511 34817 1511 4202496 6259 0 0 0 81 2 0 0 18 0 1 0 5142205 22425600 5219 1283457024 134512640 136285277 4288891936 18446744073709551615 134669462 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1087/statm: 5475 5219 234 433 0 5040 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 24492

[startup+6.30684 s]
/proc/loadavg: 1.58 1.31 1.16 2/37 1089
/proc/meminfo: memFree=242820/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=2.26
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 624 20796 0 0 1 0 211 14 15 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
[pid=1087] ppid=1074 vsize=25868 CPUtime=4.03
/proc/1087/stat : 1087 (clasp) R 1074 1074 1511 34817 1511 4202496 7268 0 0 0 401 2 0 0 25 0 1 0 5142205 26488832 6228 1283457024 134512640 136285277 4288891936 18446744073709551615 134960059 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1087/statm: 6467 6228 234 433 0 6032 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 28460

[startup+12.7087 s]
/proc/loadavg: 1.49 1.30 1.16 2/37 1090
/proc/meminfo: memFree=220756/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=2.26
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 624 20796 0 0 1 0 211 14 15 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
[pid=1087] ppid=1074 vsize=50584 CPUtime=10.43
/proc/1087/stat : 1087 (clasp) R 1074 1074 1511 34817 1511 4202496 13466 0 0 0 1037 6 0 0 25 0 1 0 5142205 51798016 12426 1283457024 134512640 136285277 4288891936 18446744073709551615 134959981 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1087/statm: 12646 12426 234 433 0 12211 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 53176

[startup+25.5126 s]
/proc/loadavg: 1.42 1.29 1.16 2/37 1091
/proc/meminfo: memFree=178844/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=2.26
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 624 20796 0 0 1 0 211 14 15 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
[pid=1087] ppid=1074 vsize=89052 CPUtime=23.23
/proc/1087/stat : 1087 (clasp) R 1074 1074 1511 34817 1511 4202496 23042 0 0 0 2312 11 0 0 25 0 1 0 5142205 91189248 22002 1283457024 134512640 136285277 4288891936 18446744073709551615 134686302 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1087/statm: 22263 22002 234 433 0 21828 0
Current children cumulated CPU time (s) 25.49
Current children cumulated vsize (KiB) 91644

[startup+51.1091 s]
/proc/loadavg: 1.27 1.26 1.15 2/37 1094
/proc/meminfo: memFree=137180/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=2.26
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 624 20796 0 0 1 0 211 14 15 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
[pid=1087] ppid=1074 vsize=129624 CPUtime=48.81
/proc/1087/stat : 1087 (clasp) R 1074 1074 1511 34817 1511 4202496 33142 0 0 0 4865 16 0 0 25 0 1 0 5142205 132734976 32102 1283457024 134512640 136285277 4288891936 18446744073709551615 134959488 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1087/statm: 32406 32102 234 433 0 31971 0
Current children cumulated CPU time (s) 51.07
Current children cumulated vsize (KiB) 132216

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

[startup+51.2091 s]
/proc/loadavg: 1.27 1.26 1.15 2/37 1094
/proc/meminfo: memFree=137180/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=2.26
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 624 20796 0 0 1 0 211 14 15 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
[pid=1087] ppid=1074 vsize=129624 CPUtime=48.91
/proc/1087/stat : 1087 (clasp) R 1074 1074 1511 34817 1511 4202496 33142 0 0 0 4875 16 0 0 25 0 1 0 5142205 132734976 32102 1283457024 134512640 136285277 4288891936 18446744073709551615 134931504 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1087/statm: 32406 32102 234 433 0 31971 0
Current children cumulated CPU time (s) 51.17
Current children cumulated vsize (KiB) 132216

[startup+57.6109 s]
/proc/loadavg: 1.23 1.25 1.15 2/37 1094
/proc/meminfo: memFree=137180/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=2.26
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 624 20796 0 0 1 0 211 14 15 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
[pid=1087] ppid=1074 vsize=129624 CPUtime=55.3
/proc/1087/stat : 1087 (clasp) R 1074 1074 1511 34817 1511 4202496 33142 0 0 0 5514 16 0 0 25 0 1 0 5142205 132734976 32102 1283457024 134512640 136285277 4288891936 18446744073709551615 134686280 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1087/statm: 32406 32102 234 433 0 31971 0
Current children cumulated CPU time (s) 57.56
Current children cumulated vsize (KiB) 132216

[startup+64.0028 s]
/proc/loadavg: 1.21 1.25 1.15 2/37 1095
/proc/meminfo: memFree=138048/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=2.26
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 624 20796 0 0 1 0 211 14 15 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
[pid=1087] ppid=1074 vsize=128040 CPUtime=61.69
/proc/1087/stat : 1087 (clasp) R 1074 1074 1511 34817 1511 4202496 33142 0 0 0 6153 16 0 0 25 0 1 0 5142205 131112960 31728 1283457024 134512640 136285277 4288891936 18446744073709551615 134963464 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1087/statm: 32010 31728 234 433 0 31575 0
Current children cumulated CPU time (s) 63.95
Current children cumulated vsize (KiB) 130632

[startup+65.6032 s]
/proc/loadavg: 1.21 1.25 1.15 2/37 1095
/proc/meminfo: memFree=138048/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=2.26
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 624 20796 0 0 1 0 211 14 15 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
[pid=1087] ppid=1074 vsize=128040 CPUtime=63.29
/proc/1087/stat : 1087 (clasp) R 1074 1074 1511 34817 1511 4202496 33142 0 0 0 6313 16 0 0 25 0 1 0 5142205 131112960 31728 1283457024 134512640 136285277 4288891936 18446744073709551615 134670159 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1087/statm: 32010 31728 234 433 0 31575 0
Current children cumulated CPU time (s) 65.55
Current children cumulated vsize (KiB) 130632

[startup+66.4035 s]
/proc/loadavg: 1.21 1.25 1.15 2/37 1095
/proc/meminfo: memFree=138048/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=2.26
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 624 20796 0 0 1 0 211 14 15 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
[pid=1087] ppid=1074 vsize=128040 CPUtime=64.09
/proc/1087/stat : 1087 (clasp) R 1074 1074 1511 34817 1511 4202496 33142 0 0 0 6393 16 0 0 25 0 1 0 5142205 131112960 31728 1283457024 134512640 136285277 4288891936 18446744073709551615 134686280 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1087/statm: 32010 31728 234 433 0 31575 0
Current children cumulated CPU time (s) 66.35
Current children cumulated vsize (KiB) 130632

[startup+67.2037 s]
/proc/loadavg: 1.19 1.24 1.15 2/37 1095
/proc/meminfo: memFree=138048/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2592 CPUtime=2.26
/proc/1074/stat : 1074 (aspcud-trendy-1) S 1073 1074 1511 34817 1511 4202496 624 20796 0 0 1 0 211 14 15 0 1 0 5142204 2654208 298 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/1074/statm: 648 298 251 194 0 35 0
[pid=1087] ppid=1074 vsize=128040 CPUtime=64.89
/proc/1087/stat : 1087 (clasp) R 1074 1074 1511 34817 1511 4202496 33142 0 0 0 6473 16 0 0 25 0 1 0 5142205 131112960 31728 1283457024 134512640 136285277 4288891936 18446744073709551615 134959924 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/1087/statm: 32010 31728 234 433 0 31575 0
Current children cumulated CPU time (s) 67.15
Current children cumulated vsize (KiB) 130632

[startup+67.4038 s]
/proc/loadavg: 1.19 1.24 1.15 2/37 1095
/proc/meminfo: memFree=138048/1048576 swapFree=0/0
[pid=1074] ppid=1073 vsize=2660 CPUtime=67.36
/proc/1074/stat : 1074 (aspcud-trendy-1) R 1073 1074 1511 34817 1511 4202496 948 56695 0 0 1 0 6700 35 20 0 1 0 5142204 2723840 320 1283457024 134512640 135304128 4294814160 18446744073709551615 4294960130 0 65538 16902 1132543225 0 0 0 17 0 0 0 0
/proc/1074/statm: 665 320 256 194 0 52 0
Current children cumulated CPU time (s) 67.36
Current children cumulated vsize (KiB) 2660

Child status: 0
Real time (s): 67.4065
CPU time (s): 67.3722
CPU user time (s): 67.0122
CPU system time (s): 0.360022
CPU usage (%): 99.9492
Max. virtual memory (cumulated for all children) (KiB): 132216

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 67.0122
system time used= 0.360022
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 58273
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= 779
involuntary context switches= 1363

runsolver used 0 second user time and 0 second system time

The end