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/80cfe9a6-9b1b-11df-965e-00163e46d37a.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//80cfe9a6-9b1b-11df-965e-00163e46d37a.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/80cfe9a6-9b1b-11df-965e-00163e46d37a.cudf.dudf-real.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.00 1.00 1.00 1/33 13243
/proc/meminfo: memFree=943864/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=3016 CPUtime=0
/proc/13243/stat : 13243 (runsolver) D 13242 13243 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 56718028 3088384 93 1283457024 134512640 134586868 4289694704 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/13243/statm: 754 93 62 19 0 53 0

[startup+0.123853 s]
/proc/loadavg: 1.00 1.00 1.00 1/33 13243
/proc/meminfo: memFree=943864/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=0
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.207874 s]
/proc/loadavg: 1.00 1.00 1.00 1/33 13243
/proc/meminfo: memFree=943864/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=0
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.308559 s]
/proc/loadavg: 1.00 1.00 1.00 1/33 13243
/proc/meminfo: memFree=943864/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=0
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.708676 s]
/proc/loadavg: 1.00 1.00 1.00 1/33 13243
/proc/meminfo: memFree=943864/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=0
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50885 s]
/proc/loadavg: 1.08 1.02 1.01 2/37 13254
/proc/meminfo: memFree=922120/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=0
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
[pid=13252] ppid=13243 vsize=3444 CPUtime=0
/proc/13252/stat : 13252 (unclasp) S 13243 13243 2160 34817 2160 4202496 403 0 5 0 0 0 0 0 25 0 1 0 56718032 3526656 272 1283457024 134512640 135121179 4289856592 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/13252/statm: 861 272 240 149 0 52 0
[pid=13253] ppid=13243 vsize=2692 CPUtime=0.01
/proc/13253/stat : 13253 (gringo) S 13243 13243 2160 34817 2160 4202496 386 0 23 0 1 0 0 0 23 0 1 0 56718032 2756608 281 1283457024 134512640 137056543 4289856272 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/13253/statm: 673 281 252 622 0 48 0
[pid=13254] ppid=13243 vsize=27320 CPUtime=1.23
/proc/13254/stat : 13254 (cudf2lp) R 13243 13243 2160 34817 2160 4202496 7718 0 15 0 120 3 0 0 25 0 1 0 56718032 27975680 6188 1283457024 134512640 135786343 4287331344 18446744073709551615 134696384 0 0 6 0 0 0 0 17 0 0 0 0
/proc/13254/statm: 6830 6188 128 311 0 6517 0
Current children cumulated CPU time (s) 1.24
Current children cumulated vsize (KiB) 36052

[startup+3.10933 s]
/proc/loadavg: 1.08 1.02 1.01 4/37 13254
/proc/meminfo: memFree=891308/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=0
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 1517 0 3 0 0 0 0 25 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
[pid=13252] ppid=13243 vsize=21892 CPUtime=0.15
/proc/13252/stat : 13252 (unclasp) R 13243 13243 2160 34817 2160 4202496 5803 0 6 0 11 4 0 0 18 0 1 0 56718032 22417408 4812 1283457024 134512640 135121179 4289856592 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13252/statm: 5473 4812 275 149 0 4664 0
[pid=13253] ppid=13243 vsize=31032 CPUtime=0.95
/proc/13253/stat : 13253 (gringo) S 13243 13243 2160 34817 2160 4202496 9287 0 23 0 93 2 0 0 18 0 1 0 56718032 31776768 5888 1283457024 134512640 137056543 4289856272 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/13253/statm: 7758 5888 253 622 0 7133 0
[pid=13254] ppid=13243 vsize=35600 CPUtime=1.74
/proc/13254/stat : 13254 (cudf2lp) R 13243 13243 2160 34817 2160 4202496 11234 0 15 0 170 4 0 0 25 0 1 0 56718032 36454400 8689 1283457024 134512640 135786343 4287331344 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/13254/statm: 8900 8689 139 311 0 8587 0
Current children cumulated CPU time (s) 2.84
Current children cumulated vsize (KiB) 91120

[startup+6.30967 s]
/proc/loadavg: 1.15 1.03 1.01 3/36 13254
/proc/meminfo: memFree=820644/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=2.13
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 12754 0 18 0 0 207 6 18 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
[pid=13252] ppid=13243 vsize=72400 CPUtime=0.68
/proc/13252/stat : 13252 (unclasp) S 13243 13243 2160 34817 2160 4202496 19792 0 6 0 57 11 0 0 18 0 1 0 56718032 74137600 17289 1283457024 134512640 135121179 4289856592 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/13252/statm: 18100 17289 277 149 0 17291 0
[pid=13253] ppid=13243 vsize=122284 CPUtime=3.22
/proc/13253/stat : 13253 (gringo) R 13243 13243 2160 34817 2160 4202496 37367 0 23 0 310 12 0 0 19 0 1 0 56718032 125218816 24912 1283457024 134512640 137056543 4289856272 18446744073709551615 134904332 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13253/statm: 30571 24912 268 622 0 29946 0
Current children cumulated CPU time (s) 6.03
Current children cumulated vsize (KiB) 197280

[startup+12.7143 s]
/proc/loadavg: 1.14 1.03 1.01 2/35 13254
/proc/meminfo: memFree=848320/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=5.75
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 50125 0 41 0 0 553 22 18 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
[pid=13252] ppid=13243 vsize=101888 CPUtime=6.69
/proc/13252/stat : 13252 (unclasp) R 13243 13243 2160 34817 2160 4202496 108061 0 7 0 617 52 0 0 25 0 1 0 56718032 104333312 23555 1283457024 134512640 135121179 4289856592 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13252/statm: 25472 23555 319 149 0 24663 0
Current children cumulated CPU time (s) 12.44
Current children cumulated vsize (KiB) 104484

[startup+25.5095 s]
/proc/loadavg: 1.11 1.03 1.01 2/35 13254
/proc/meminfo: memFree=849560/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=5.75
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 50125 0 41 0 0 553 22 18 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
[pid=13252] ppid=13243 vsize=99528 CPUtime=19.47
/proc/13252/stat : 13252 (unclasp) R 13243 13243 2160 34817 2160 4202496 294118 0 7 0 1808 139 0 0 25 0 1 0 56718032 101916672 22978 1283457024 134512640 135121179 4289856592 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13252/statm: 24882 22978 319 149 0 24073 0
Current children cumulated CPU time (s) 25.22
Current children cumulated vsize (KiB) 102124

[startup+51.1087 s]
/proc/loadavg: 1.07 1.03 1.01 2/35 13254
/proc/meminfo: memFree=849436/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=5.75
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 50125 0 41 0 0 553 22 18 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
[pid=13252] ppid=13243 vsize=98256 CPUtime=45.05
/proc/13252/stat : 13252 (unclasp) R 13243 13243 2160 34817 2160 4202496 650931 0 7 0 4220 285 0 0 25 0 1 0 56718032 100614144 22677 1283457024 134512640 135121179 4289856592 18446744073709551615 134734477 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13252/statm: 24564 22677 319 149 0 23755 0
Current children cumulated CPU time (s) 50.8
Current children cumulated vsize (KiB) 100852

[startup+102.309 s]
/proc/loadavg: 1.03 1.02 1.00 2/35 13254
/proc/meminfo: memFree=847824/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=5.75
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 50125 0 41 0 0 553 22 18 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
[pid=13252] ppid=13243 vsize=99548 CPUtime=96.2
/proc/13252/stat : 13252 (unclasp) R 13243 13243 2160 34817 2160 4202496 1343940 0 7 0 9035 585 0 0 25 0 1 0 56718032 101937152 23027 1283457024 134512640 135121179 4289856592 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13252/statm: 24887 23027 321 149 0 24078 0
Current children cumulated CPU time (s) 101.95
Current children cumulated vsize (KiB) 102144

[startup+162.312 s]
/proc/loadavg: 1.01 1.02 1.00 2/35 13254
/proc/meminfo: memFree=848940/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=5.75
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 50125 0 41 0 0 553 22 18 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
[pid=13252] ppid=13243 vsize=101936 CPUtime=156.17
/proc/13252/stat : 13252 (unclasp) R 13243 13243 2160 34817 2160 4202496 2153978 0 7 0 14659 958 0 0 25 0 1 0 56718032 104382464 23649 1283457024 134512640 135121179 4289856592 18446744073709551615 134980992 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13252/statm: 25484 23649 321 149 0 24675 0
Current children cumulated CPU time (s) 161.92
Current children cumulated vsize (KiB) 104532

[startup+222.311 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 13259
/proc/meminfo: memFree=846560/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=5.75
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 50125 0 41 0 0 553 22 18 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
[pid=13252] ppid=13243 vsize=98284 CPUtime=216.13
/proc/13252/stat : 13252 (unclasp) R 13243 13243 2160 34817 2160 4202496 2942673 0 7 0 20313 1300 0 0 25 0 1 0 56718032 100642816 22739 1283457024 134512640 135121179 4289856592 18446744073709551615 4159681605 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13252/statm: 24571 22739 321 149 0 23762 0
Current children cumulated CPU time (s) 221.88
Current children cumulated vsize (KiB) 100880

[startup+282.302 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 13265
/proc/meminfo: memFree=846932/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=5.75
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 50125 0 41 0 0 553 22 18 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
[pid=13252] ppid=13243 vsize=99588 CPUtime=276.07
/proc/13252/stat : 13252 (unclasp) R 13243 13243 2160 34817 2160 4202496 3706868 0 7 0 25959 1648 0 0 25 0 1 0 56718032 101978112 23108 1283457024 134512640 135121179 4289856592 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13252/statm: 24897 23108 321 149 0 24088 0
Current children cumulated CPU time (s) 281.82
Current children cumulated vsize (KiB) 102184



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+290.515 s]
/proc/loadavg: 1.00 1.00 1.00 2/36 13265
/proc/meminfo: memFree=845212/1048576 swapFree=0/0
[pid=13243] ppid=13242 vsize=2596 CPUtime=5.75
/proc/13243/stat : 13243 (aspuncud-user-1) S 13242 13243 2160 34817 2160 4202496 573 50125 0 41 0 0 553 22 18 0 1 0 56718028 2658304 298 1283457024 134512640 135304128 4289926400 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/13243/statm: 649 298 251 194 0 36 0
[pid=13252] ppid=13243 vsize=101976 CPUtime=284.27
/proc/13252/stat : 13252 (unclasp) R 13243 13243 2160 34817 2160 4202496 3814490 0 7 0 26729 1698 0 0 25 0 1 0 56718032 104423424 23707 1283457024 134512640 135121179 4289856592 18446744073709551615 134977774 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/13252/statm: 25494 23707 321 149 0 24685 0
Current children cumulated CPU time (s) 290.02
Current children cumulated vsize (KiB) 104572

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.56
CPU time (s): 290.05
CPU user time (s): 272.829
CPU system time (s): 17.2211
CPU usage (%): 99.8245
Max. virtual memory (cumulated for all children) (KiB): 200472

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 272.829
system time used= 17.2211
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 3867578
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= 6763
involuntary context switches= 8843

runsolver used 0 second user time and 0 second system time

The end