[hercules-390] hyperion slower than 3.12

[[e-mail] [hercules-390]]

I have an automated startup of a
slightly modified MVS 3.8j.

I did some time trials of how it runs
under *standard* Hercules versions:

The time shown is as seen by my
Windows batch file. I have confirmed
from the hercules log (see below
extracts) that the extra time is spent
in hercules/MVS, not something external.

Hyperion:
5.56, 5.3, 5.18

3.12:
4.8, 3.62, 4.67, 3.59, 3.7, 3.59

3.07:
3.65, 3.55, 3.56

I ran 3.12 more times because of the
initial time discrepancies.

Any suggestions?

Thanks. Paul.




11:58:55 Hercules Version 3.12
11:58:55 (c)Copyright 1999-2015 by Roger Bowler, Jan Jaeger, and others
11:58:55 Built on Nov 26 2015 at 18:05:07
11:58:55 Build information:
11:58:55 Windows (MSVC) build for i386
11:58:55 Modes: S/370 ESA/390 z/Arch
11:58:55 Max CPU Engines: 8
11:58:55 Using fthreads instead of pthreads
11:58:55 Dynamic loading support
11:58:55 Using shared libraries
11:58:55 HTTP Server support
11:58:55 No SIGABEND handler
11:58:55 Regular Expressions support
11:58:55 Automatic Operator support
11:58:55 Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8 fetch_dw store_dw
11:58:55 Running on PAUL-DELL Windows_NT-6.2 i686 MP=8
...
11:58:58 HHCHD901I Calling logger_term
11:58:58 HHCLG014I logger thread terminating



12:01:58 HHC01413I Hercules version 4.0.0.0 (4.0.0.0)
12:01:58 HHC01414I (C) Copyright 1999-2016 by Roger Bowler, Jan Jaeger, and others
12:01:58 HHC01415I Build date: Dec 16 2016 at 14:14:30
12:01:58 HHC01417I Built with: Microsoft Visual C 190024215 1
12:01:58 HHC01417I Build type: Windows MSVC i386 host architecture build
12:01:58 HHC01417I Modes: S/370 ESA/390 z/Arch
12:01:58 HHC01417I Max CPU Engines: 32
12:01:58 HHC01417I Using Fish threads Threading Model
12:01:58 HHC01417I Using Error-Checking Mutex Locking Model
12:01:58 HHC01417I With Syncio support
12:01:58 HHC01417I With Shared Devices support
12:01:58 HHC01417I With Dynamic loading support
12:01:58 HHC01417I Using shared libraries
12:01:58 HHC01417I With External GUI support
12:01:58 HHC01417I With Partial TCP keepalive support
12:01:58 HHC01417I With IPV6 support
12:01:58 HHC01417I With HTTP Server support
12:01:58 HHC01417I With sqrtl support
12:01:58 HHC01417I Without SIGABEND handler
12:01:58 HHC01417I With CCKD BZIP2 support
12:01:58 HHC01417I With HET BZIP2 support
12:01:58 HHC01417I With ZLIB support
12:01:58 HHC01417I With Regular Expressions support
12:01:58 HHC01417I With Object REXX support
12:01:58 HHC01417I With Regina REXX support
12:01:58 HHC01417I With Automatic Operator support
12:01:58 HHC01417I Without National Language Support
12:01:58 HHC01417I Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8 fetch_dw store_dw hatomics=msvcIntrinsics
12:01:58 HHC01417I Running on: PAUL-DELL (Windows-6.2.9200 Intel(R) x64) LP=8, Cores=4, CPUs=1
12:01:58 HHC00018W Hercules is NOT running in elevated mode
12:01:58 HHC02323W This build of Hercules has only partial TCP keepalive support
12:01:58 HHC01508I HDL: loadable module directory is c:/herc380/
12:01:58 HHC00150I Crypto module loaded (c) Copyright 2003-2016 by Bernard van der Helm
12:01:58 HHC00151I Activated facility: Message Security Assist
12:01:58 HHC00151I Activated facility: Message Security Assist Extension 1, 2, 3 and 4
12:01:58 HHC00100I Thread id 000041fc, prio 15, name Processor CP00 started
...
12:02:03 HHC02103I Logger: logger thread terminating
12:02:03 HHC00101I Thread id 0000226c, prio 0, name Control panel ended
12:02:03 HHC02264I Script 7: file conf/termherc2.rc processing ended

[[e-mail] [hercules-390]]

Post by ***@yahoo.com.au [hercules-390]
The time shown is as seen by my
Windows batch file. I have confirmed
from the hercules log (see below
extracts) that the extra time is spent
in hercules/MVS, not something external.

BTW, it would be helpful in pinpointing
such timing questions if there was an
option to log hundredths or thousandths
of a second.

BFN. Paul.

[Joe Monk [e-mail] [hercules-390]]

You're seriously complaining about *2 seconds*?

Joe

Post by ***@yahoo.com.au [hercules-390]
I have an automated startup of a
slightly modified MVS 3.8j.
I did some time trials of how it runs
The time shown is as seen by my
Windows batch file. I have confirmed
from the hercules log (see below
extracts) that the extra time is spent
in hercules/MVS, not something external.
5.56, 5.3, 5.18
4.8, 3.62, 4.67, 3.59, 3.7, 3.59
3.65, 3.55, 3.56
I ran 3.12 more times because of the
initial time discrepancies.
Any suggestions?
Thanks. Paul.
11:58:55 Hercules Version 3.12
11:58:55 (c)Copyright 1999-2015 by Roger Bowler, Jan Jaeger, and others
11:58:55 Built on Nov 26 2015 at 18:05:07
11:58:55 Windows (MSVC) build for i386
11:58:55 Modes: S/370 ESA/390 z/Arch
11:58:55 Max CPU Engines: 8
11:58:55 Using fthreads instead of pthreads
11:58:55 Dynamic loading support
11:58:55 Using shared libraries
11:58:55 HTTP Server support
11:58:55 No SIGABEND handler
11:58:55 Regular Expressions support
11:58:55 Automatic Operator support
11:58:55 Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8 fetch_dw
store_dw
11:58:55 Running on PAUL-DELL Windows_NT-6.2 i686 MP=8
...
11:58:58 HHCHD901I Calling logger_term
11:58:58 HHCLG014I logger thread terminating
12:01:58 HHC01413I Hercules version 4.0.0.0 (4.0.0.0)
12:01:58 HHC01414I (C) Copyright 1999-2016 by Roger Bowler, Jan Jaeger, and others
12:01:58 HHC01415I Build date: Dec 16 2016 at 14:14:30
12:01:58 HHC01417I Built with: Microsoft Visual C 190024215 1
12:01:58 HHC01417I Build type: Windows MSVC i386 host architecture build
12:01:58 HHC01417I Modes: S/370 ESA/390 z/Arch
12:01:58 HHC01417I Max CPU Engines: 32
12:01:58 HHC01417I Using Fish threads Threading Model
12:01:58 HHC01417I Using Error-Checking Mutex Locking Model
12:01:58 HHC01417I With Syncio support
12:01:58 HHC01417I With Shared Devices support
12:01:58 HHC01417I With Dynamic loading support
12:01:58 HHC01417I Using shared libraries
12:01:58 HHC01417I With External GUI support
12:01:58 HHC01417I With Partial TCP keepalive support
12:01:58 HHC01417I With IPV6 support
12:01:58 HHC01417I With HTTP Server support
12:01:58 HHC01417I With sqrtl support
12:01:58 HHC01417I Without SIGABEND handler
12:01:58 HHC01417I With CCKD BZIP2 support
12:01:58 HHC01417I With HET BZIP2 support
12:01:58 HHC01417I With ZLIB support
12:01:58 HHC01417I With Regular Expressions support
12:01:58 HHC01417I With Object REXX support
12:01:58 HHC01417I With Regina REXX support
12:01:58 HHC01417I With Automatic Operator support
12:01:58 HHC01417I Without National Language Support
12:01:58 HHC01417I Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8
fetch_dw store_dw hatomics=msvcIntrinsics
12:01:58 HHC01417I Running on: PAUL-DELL (Windows-6.2.9200 Intel(R) x64)
LP=8, Cores=4, CPUs=1
12:01:58 HHC00018W Hercules is NOT running in elevated mode
12:01:58 HHC02323W This build of Hercules has only partial TCP keepalive support
12:01:58 HHC01508I HDL: loadable module directory is c:/herc380/
12:01:58 HHC00150I Crypto module loaded (c) Copyright 2003-2016 by Bernard van der Helm
12:01:58 HHC00151I Activated facility: Message Security Assist
12:01:58 HHC00151I Activated facility: Message Security Assist Extension 1, 2, 3 and 4
12:01:58 HHC00100I Thread id 000041fc, prio 15, name Processor CP00 started
...
12:02:03 HHC02103I Logger: logger thread terminating
12:02:03 HHC00101I Thread id 0000226c, prio 0, name Control panel ended
12:02:03 HHC02264I Script 7: file conf/termherc2.rc processing ended

[[e-mail] [hercules-390]]

Post by Joe Monk ***@gmail.com [hercules-390]
You're seriously complaining about *2 seconds*?

Yes, I wasn't expecting Hyperion to
introduce inefficiencies that take my
job runtime from 3.6 seconds to
5.18 seconds, a 44% increase.

44% is just my particular testcase
too. Other people might experience
bigger runtime increases depending
on what they are doing. I don't know.
I don't know what is causing it.

BFN. Paul.

[Joe Monk [e-mail] [hercules-390]]

Is your hercules 4.00 x64?


Joe

Post by ***@yahoo.com.au [hercules-390]

Post by Joe Monk ***@gmail.com [hercules-390]
You're seriously complaining about *2 seconds*?

Yes, I wasn't expecting Hyperion to
introduce inefficiencies that take my
job runtime from 3.6 seconds to
5.18 seconds, a 44% increase.
44% is just my particular testcase
too. Other people might experience
bigger runtime increases depending
on what they are doing. I don't know.
I don't know what is causing it.
BFN. Paul.

[[e-mail] [hercules-390]]

Post by Joe Monk ***@gmail.com [hercules-390]
Is your hercules 4.00 x64?

No, all tests are 32-bit:

12:11:26 HHC01413I Hercules version 4.0.0.0 (4.0.0.0)
12:11:26 HHC01414I (C) Copyright 1999-2016 by Roger Bowler, Jan Jaeger, and others
12:11:26 HHC01415I Build date: Dec 16 2016 at 14:14:30
12:11:26 HHC01417I Built with: Microsoft Visual C 190024215 1
12:11:26 HHC01417I Build type: Windows MSVC i386 host architecture build

BFN. Paul.

[Jeremy Nicoll [e-mail] [hercules-390]]

Post by ***@yahoo.com.au [hercules-390]

Post by Joe Monk ***@gmail.com [hercules-390]
You're seriously complaining about *2 seconds*?

Yes, I wasn't expecting Hyperion to
introduce inefficiencies that take my
job runtime from 3.6 seconds to
5.18 seconds, a 44% increase.

As you said earlier, in the absence of fractional seconds, it's hard to
be precise. The
actual elapsed time between two timestamped records:

12:01:58 HHC00100I Thread id 000041fc, prio 15, name Processor CP00
started
...
12:02:03 HHC02103I Logger: logger thread terminating

could be as little as a fraction over 4 seconds (if eg those were
01:58.99 and 02:03.01),
or as much as very nearly 6 seconds (01:58.01 and 02:03.99).

That means your error margin is far too large/significant a portion of
the overall time
being measured. To get around this you need to make the amount of work
being done
by the thing being measured significantly larger - I'd suggest a job of
10 - 100 times the
duration of the present one.

If there's other stuff running on your pc at the same time, ideally it
needs stopped. If you
can't do that you'll need to run many tests to average out the effect of
background workload.

[[e-mail] [hercules-390]]

Post by Jeremy Nicoll ***@letterboxes.org [hercules-390]
That means your error margin is far too
large/significant a portion of
the overall time

I am using the MSDOS "time" command
to get hundreds of a second in the overall
execution (all automated). That is how I
know that Hyperion is 44% slower than 3.12.

Without the hundredths/thousandths in
the log it just makes it difficult to pinpoint
exactly which bit is slower. But I do know
that overall it is slower.

Post by Jeremy Nicoll ***@letterboxes.org [hercules-390]
If there's other stuff running on your
pc at the same time, ideally it
needs stopped.

I believe I did the tests after a reboot,
or at least with nothing significant
running. I did multiple tests and am
happy to use the lowest figures.

BFN. Paul.

[Joe Monk [e-mail] [hercules-390]]

"That is how I know that Hyperion is 44% slower than 3.12."

You dont know any such thing.

For instance:

3.12: Max CPU Engines: 8

4.0: Max CPU Engines: 32

You're not even running apples to apples comparisons. How much overhead are
you introducing by running 4 times the number of CPU's in 4.0?

How about reducing to 1 CPU , same MAINSIZE and then running your
comparisons?

Joe

Post by ***@yahoo.com.au [hercules-390]

Post by Jeremy Nicoll ***@letterboxes.org [hercules-390]
That means your error margin is far too
large/significant a portion of
the overall time

I am using the MSDOS "time" command
to get hundreds of a second in the overall
execution (all automated). That is how I
know that Hyperion is 44% slower than 3.12.
Without the hundredths/thousandths in
the log it just makes it difficult to pinpoint
exactly which bit is slower. But I do know
that overall it is slower.

Post by Jeremy Nicoll ***@letterboxes.org [hercules-390]
If there's other stuff running on your
pc at the same time, ideally it
needs stopped.

I believe I did the tests after a reboot,
or at least with nothing significant
running. I did multiple tests and am
happy to use the lowest figures.
BFN. Paul.

[[e-mail] [hercules-390]]

Post by Joe Monk ***@gmail.com [hercules-390]

Post by Joe Monk ***@gmail.com [hercules-390]
That is how I know that Hyperion is 44% slower than 3.12.

You dont know any such thing.

I do for the test I was running, ie the
exact same config file for both. If
something has changed in Hyperion
that makes the default slower, then
so be it, Hyperion is slower. Even if
it can be tuned to not be slower.

Post by Joe Monk ***@gmail.com [hercules-390]
3.12: Max CPU Engines: 8
4.0: Max CPU Engines: 32
You're not even running apples to
apples comparisons.

Yes I am. I'm using the same config
file. That's a perfectly valid test. If
you think the above is a problem,
then perhaps Hyperion shouldn't
have changed the above default.

Post by Joe Monk ***@gmail.com [hercules-390]
How much overhead are you introducing
by running 4 times the number of CPU's in 4.0?

That should be worded "how much overhead
is HYPERION introducing by changing the
default number of CPUs".

Post by Joe Monk ***@gmail.com [hercules-390]
How about reducing to 1 CPU , same MAINSIZE
and then running your comparisons?

I'm using the exact same config file, so
MAINSIZE is the same, ie 200 MiB.

I don't know how to reduce the number
of CPUs. I tried adding this:

C:\mvs380\conf>cvs diff mvs380.conf
Index: mvs380.conf
===================================================================
RCS file: /cvsroot/mvs380/mvs380/conf/mvs380.conf,v
retrieving revision 1.11
diff -r1.11 mvs380.conf
65a66

Post by Joe Monk ***@gmail.com [hercules-390]
MAXCPU 1

C:\mvs380\conf>grep MAX mvs380.conf
DEVTMAX 0
# MAXCPU 3
MAXCPU 1


C:\mvs380\conf>grep NUMCPU mvs380.conf
NUMCPU 1


But the log still shows:

22:28:45 HHC01417I Max CPU Engines: 32


I think that might be set at compile time.
I am using pre-built binaries for both
3.12 and Hyperion. Again, if Hyperion
is slower because something changed
at compile time, or even if it is compiled
using a different version of the compiler,
then that is exactly what we should be
comparing (as I am already), with a
view to switching back to compiling
using the same compiler that 3.12 uses,
or whatever it is that is introducing the
inefficiency.

BFN. Paul.

[Vince Coen [e-mail] [hercules-390]]

Paul;


Have you stopped all un-needed tasks.

Examples are anti virus tools, defragging tools and other similar as
they run all the time subject to what you are running in foreground and
at differing times etc.

Try suspending or terminating them first then do the same tests.

Another point is that on the assumption that there are not background
tasks running that will interfere with foreground the timings should be
the same or very similar for doing 'EXACTLY" the same thing - - -
unless you have a de-fragging problem with your drives and specifically
with the one holding your MVS dasd systems.

I strongly recommend you do a defrag pass any way as a JIC.

Vince

Post by ***@yahoo.com.au [hercules-390]

Post by Joe Monk ***@gmail.com [hercules-390]
You're seriously complaining about *2 seconds*?

Yes, I wasn't expecting Hyperion to
introduce inefficiencies that take my
job runtime from 3.6 seconds to
5.18 seconds, a 44% increase.
44% is just my particular testcase
too. Other people might experience
bigger runtime increases depending
on what they are doing. I don't know.
I don't know what is causing it.
BFN. Paul.

[[e-mail] [hercules-390]]

Post by Vince Coen ***@gmail.com [hercules-390]
Have you stopped all un-needed tasks.

I don't believe I need to do all that
(which I don't know how to do) in
order to be confident of the result.

I just created some new scripts, here:

C:\mvs380_work\mvshd6>type master.bat
del time.txt
call doit2.bat
call doit2.bat

C:\mvs380_work\mvshd6>type doit2.bat
pushd \herc380
unzip -o \download\hercules-3.12-w32
popd
call doit
call doit
pushd \herc380
unzip -o \download\Hercules-4.0.0-rc0-win-x86.zip
popd
call doit
call doit

C:\mvs380_work\mvshd6>type doit.bat
time <NUL: >>time.txt
del out.txt
call mvshd in.txt out.txt
time <NUL: >>time.txt

C:\mvs380_work\mvshd6>


And I rebooted my system, and
did one dummy run of "master",
then a second run, which has
the following results:

C:\mvs380_work\mvshd6>type time.txt
The current time is: 0:10:56.17
Enter the new time: The current time is: 0:10:59.91
Enter the new time: The current time is: 0:10:59.92
Enter the new time: The current time is: 0:11:03.51
Enter the new time: The current time is: 0:11:04.71
Enter the new time: The current time is: 0:11:09.96
Enter the new time: The current time is: 0:11:09.96
Enter the new time: The current time is: 0:11:15.03
Enter the new time: The current time is: 0:11:16.73
Enter the new time: The current time is: 0:11:20.43
Enter the new time: The current time is: 0:11:20.43
Enter the new time: The current time is: 0:11:24.02
Enter the new time: The current time is: 0:11:25.23
Enter the new time: The current time is: 0:11:30.62
Enter the new time: The current time is: 0:11:30.62
Enter the new time: The current time is: 0:11:35.69
Enter the new time:
C:\mvs380_work\mvshd6>zcalc 59.91-56.17
Calculated Value is 3.740000
Thank you for using the calculator

C:\mvs380_work\mvshd6>zcalc 63.51-59.92
Calculated Value is 3.590000
Thank you for using the calculator

C:\mvs380_work\mvshd6>zcalc 9.96-4.71
Calculated Value is 5.250000
Thank you for using the calculator

C:\mvs380_work\mvshd6>zcalc 15.03-9.96
Calculated Value is 5.070000
Thank you for using the calculator

C:\mvs380_work\mvshd6>zcalc 20.43-16.73
Calculated Value is 3.700000
Thank you for using the calculator

C:\mvs380_work\mvshd6>zcalc 24.02-20.43
Calculated Value is 3.590000
Thank you for using the calculator

C:\mvs380_work\mvshd6>zcalc 30.62-25.23
Calculated Value is 5.390000
Thank you for using the calculator

C:\mvs380_work\mvshd6>zcalc 35.69-30.62
Calculated Value is 5.070000
Thank you for using the calculator

C:\mvs380_work\mvshd6>


So best time for 3.12 was 3.59 and
best time for Hyperion was 5.07.

You're not really going to say that
the defrag only kicked in while I was
running Hyperion, are you? If so, and
you think 3.12 vs Hyperion is an even
bet, then I would literally like to bet
with you.

If you think it is an even bet, then I
will give you 4:1 odds and I will rerun
the above as many times as you like.
If Hyperion beats or equals 3.12 50%
of the time you will make a killing. :-)

BFN. Paul.

[Jeremy Nicoll [e-mail] [hercules-390]]

Post by ***@yahoo.com.au [hercules-390]
C:\mvs380_work\mvshd6>type doit.bat
time <NUL: >>time.txt
del out.txt
call mvshd in.txt out.txt
time <NUL: >>time.txt

The thing you're testing is(?): call mvshd in.txt out.txt

Are the contents of in.txt and out.txt invariant across all
these tests?

Is what's being tested:
start up hercules
ipl an mvs system
run a single job
shutdown mvs
quiesce (if one does) hercules

?

Suppose the bit that would matter for most people, "run a single job",
is running much faster in Hyperion than the other system. Would your
test files show you that?

Have you tried to work out how long each stage takes?

[[e-mail] [hercules-390]]

The thing you're testing is(?): call mvshd in.txt out.txt

Yes, that's a batch file to run HEXDUMP
on MVS.

Are the contents of in.txt and out.txt invariant across all
these tests?

in.txt yes. out.txt is not being used
because hetget is failing because
it doesn't have the Hercules/380
extensions.

It fails equally on 3.12 and Hyperion.

start up hercules
ipl an mvs system
run a single job

Yes.

shutdown mvs
quiesce (if one does) hercules

I shut down MVS by "pulling the
power cord", ie typing "quit" which
is nearly instantaneous.

Suppose the bit that would matter
for most people, "run a single job",

Possibly. For me I always IPL MVS
in order to run a single job, so the
IPL time is a significant portion of
the run time if I'm doing something
trivial like running hexdump on a
small file.

is running much faster in Hyperion
than the other system. Would your
test files show you that?

The logging doesn't have the granularity
to "debug" a 5 second runtime.

Have you tried to work out how long
each stage takes?

I can't sensibly compare 3.12 vs
Hyperion unless the logging for both
is given in tenths, hundredths or
thousandths.

In fact, it is difficult enough to just
prove that the time being taken is
in the running of Hercules proper
rather than the hetget etc that I
run before and after Hercules.

BFN. Paul.

[[e-mail] [hercules-390]]

Post by ***@yahoo.com.au [hercules-390]
C:\mvs380_work\mvshd6>zcalc 24.02-20.43
Calculated Value is 3.590000
Thank you for using the calculator
C:\mvs380_work\mvshd6>zcalc 30.62-25.23
Calculated Value is 5.390000
Thank you for using the calculator
C:\mvs380_work\mvshd6>zcalc 35.69-30.62
Calculated Value is 5.070000
Thank you for using the calculator
C:\mvs380_work\mvshd6>
So best time for 3.12 was 3.59 and
best time for Hyperion was 5.07.

I will post the complete log for the
3rd-last run which has the best time
for 3.12, and the last run which has
the best time for Hyperion.

In two separate messages.

The 1-second-granularity means you
can't do a lot of analysis, but at least
you can have confidence that it is the
running of Hercules proper that is
where the time is being spent, and
thus where the slow-down has
occurred.

That is also clear when running it
manually. The console starts up
very quickly, and once it disappears
I get the prompt quickly too.

BFN. Paul.

[[e-mail] [hercules-390]]

3.12:

00:11:20 Hercules Version 3.12
00:11:20 (c)Copyright 1999-2015 by Roger Bowler, Jan Jaeger, and others
00:11:20 Built on Nov 26 2015 at 18:05:07
00:11:20 Build information:
00:11:20 Windows (MSVC) build for i386
00:11:20 Modes: S/370 ESA/390 z/Arch
00:11:20 Max CPU Engines: 8
00:11:20 Using fthreads instead of pthreads
00:11:20 Dynamic loading support
00:11:20 Using shared libraries
00:11:20 HTTP Server support
00:11:20 No SIGABEND handler
00:11:20 Regular Expressions support
00:11:20 Automatic Operator support
00:11:20 Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8 fetch_dw store_dw
00:11:20 Running on PAUL-DELL Windows_NT-6.2 i686 MP=8
00:11:20 HHCHD018I Loadable module directory is hercules
00:11:20 Crypto module loaded (c) Copyright Bernard van der Helm, 2003-2010
00:11:20 Active: Message Security Assist
00:11:20 Message Security Assist Extension 1
00:11:20 Message Security Assist Extension 2
00:11:20 Message Security Assist Extension 3
00:11:20 Message Security Assist Extension 4
00:11:20 HHCPN210I Default Allowed AUTOMOUNT directory = "c:\mvs380\"
00:11:20 HHCHT001I HTTP listener thread started: tid=00002E30, pid=4904
00:11:20 HHCCF065I Hercules: tid=00000E20, pid=4904, pgid=4904, priority=8
00:11:20 HHCHT013I Using HTTPROOT directory "c:\herc380\html\"
00:11:20 HHCHT006I Waiting for HTTP requests on port 8081
00:11:20 HHCSD004I Device 000C bound to socket 127.0.0.1:3505
00:11:20 HHCSD020I Socketdevice listener thread started: tid=00001A54, pid=4904
00:11:20 HHCCF083I conf/mvs380.conf Including conf/mvs380_DASD.conf at 123 .
00:11:20 HHCDA004I opening dasd/mvsres.148 readonly
00:11:20 HHCDA020I dasd/mvsres.148 cyls=560 heads=30 tracks=16800 trklen=19456
00:11:20 HHCDA004I opening dasd/sort01.131 readonly
00:11:20 HHCDA020I dasd/sort01.131 cyls=200 heads=20 tracks=4000 trklen=7680
00:11:20 HHCDA004I opening dasd/sort02.132 readonly
00:11:20 HHCDA020I dasd/sort02.132 cyls=200 heads=20 tracks=4000 trklen=7680
00:11:20 HHCDA004I opening dasd/sort03.133 readonly
00:11:20 HHCDA020I dasd/sort03.133 cyls=200 heads=20 tracks=4000 trklen=7680
00:11:20 HHCDA004I opening dasd/sort04.134 readonly
00:11:20 HHCDA020I dasd/sort04.134 cyls=200 heads=20 tracks=4000 trklen=7680
00:11:20 HHCDA004I opening dasd/sort05.135 readonly
00:11:20 HHCDA020I dasd/sort05.135 cyls=200 heads=20 tracks=4000 trklen=7680
00:11:20 HHCDA004I opening dasd/sort06.136 readonly
00:11:20 HHCDA020I dasd/sort06.136 cyls=200 heads=20 tracks=4000 trklen=7680
00:11:20 HHCDA004I opening dasd/work00.140 readonly
00:11:20 HHCDA020I dasd/work00.140 cyls=560 heads=30 tracks=16800 trklen=19456
00:11:20 HHCDA020I dasd/hasp00.152 cyls=404 heads=19 tracks=7676 trklen=13312
00:11:20 HHCDA020I dasd/page00.160 cyls=698 heads=12 tracks=8376 trklen=8704
00:11:20 HHCDA020I dasd/page01.161 cyls=698 heads=12 tracks=8376 trklen=8704
00:11:20 HHCDA020I dasd/page02.162 cyls=698 heads=12 tracks=8376 trklen=8704
00:11:20 HHCDA020I dasd/work01.170 cyls=962 heads=12 tracks=11544 trklen=35840
00:11:20 HHCDA004I opening dasd/work02.180 readonly
00:11:20 HHCDA020I dasd/work02.180 cyls=886 heads=15 tracks=13290 trklen=47616
00:11:20 HHCDA004I opening dasd/work03.190 readonly
00:11:20 HHCDA020I dasd/work03.190 cyls=1114 heads=15 tracks=16710 trklen=56832
00:11:20 HHCDA004I opening dasd/mvscat.191 readonly
00:11:20 HHCDA020I dasd/mvscat.191 cyls=1114 heads=15 tracks=16710 trklen=56832
00:11:20 HHCDA004I opening dasd/seasik.192 readonly
00:11:20 HHCDA020I dasd/seasik.192 cyls=1114 heads=15 tracks=16710 trklen=56832
00:11:20 HHCDA020I dasd/mvssrc.193 cyls=2226 heads=15 tracks=33390 trklen=56832
00:11:20 HHCDA002E 01B4:File not found or invalid 'dasd/pub004.1b4'
00:11:20 HHCCF044E Initialization failed for device 01B4
00:11:20 HHCDA004I opening dasd/pub000.240 readonly
00:11:20 HHCDA020I dasd/pub000.240 cyls=560 heads=30 tracks=16800 trklen=19456
00:11:20 HHCDA004I opening dasd/mvsdlb.248 readonly
00:11:20 HHCDA020I dasd/mvsdlb.248 cyls=560 heads=30 tracks=16800 trklen=19456
00:11:20 HHCDA004I opening dasd/pub002.280 readonly
00:11:20 HHCDA020I dasd/pub002.280 cyls=1772 heads=15 tracks=26580 trklen=47616
00:11:20 HHCDA004I opening dasd/tmptmp.2b1 readonly
00:11:20 HHCDA020I dasd/tmptmp.2b1 cyls=1114 heads=15 tracks=16710 trklen=56832
00:11:20 HHCDA004I opening dasd/xmit90.2b2 readonly
00:11:20 HHCDA020I dasd/xmit90.2b2 cyls=1114 heads=15 tracks=16710 trklen=56832
00:11:20 HHCDA004I opening dasd/start1.150 readonly
00:11:20 HHCDA020I dasd/start1.150 cyls=808 heads=19 tracks=15352 trklen=13312
00:11:20 HHCDA004I opening dasd/spool0.151 readonly
00:11:20 HHCDA020I dasd/spool0.151 cyls=808 heads=19 tracks=15352 trklen=13312
00:11:20 HHCDA004I opening dasd/cbt000.340 readonly
00:11:20 HHCDA020I dasd/cbt000.340 cyls=555 heads=30 tracks=16650 trklen=19456
00:11:20 HHCDA004I opening dasd/cbt001.341 readonly
00:11:20 HHCDA020I dasd/cbt001.341 cyls=555 heads=30 tracks=16650 trklen=19456
00:11:20 HHCDA004I opening dasd/cbt002.342 readonly
00:11:20 HHCDA020I dasd/cbt002.342 cyls=555 heads=30 tracks=16650 trklen=19456
00:11:20 HHCDA004I opening dasd/cbtcat.343 readonly
00:11:20 HHCDA020I dasd/cbtcat.343 cyls=555 heads=30 tracks=16650 trklen=19456
00:11:20 HHCDA004I opening dasd/src000.348 readonly
00:11:20 HHCDA020I dasd/src000.348 cyls=555 heads=30 tracks=16650 trklen=19456
00:11:20 HHCDA004I opening dasd/src001.349 readonly
00:11:20 HHCDA020I dasd/src001.349 cyls=555 heads=30 tracks=16650 trklen=19456
00:11:20 HHCDA004I opening dasd/src002.34a readonly
00:11:20 HHCDA020I dasd/src002.34a cyls=555 heads=30 tracks=16650 trklen=19456
00:11:20 HHCDA004I opening dasd/srccat.34b readonly
00:11:20 HHCDA020I dasd/srccat.34b cyls=555 heads=30 tracks=16650 trklen=19456
00:11:20 HHCDA004I opening dasd/smp001.149 readonly
00:11:20 HHCDA020I dasd/smp001.149 cyls=560 heads=30 tracks=16800 trklen=19456
00:11:20 HHCDA004I opening dasd/smp002.14a readonly
00:11:20 HHCDA020I dasd/smp002.14a cyls=560 heads=30 tracks=16800 trklen=19456
00:11:20 HHCDA004I opening dasd/smp003.14b readonly
00:11:20 HHCDA020I dasd/smp003.14b cyls=560 heads=30 tracks=16800 trklen=19456
00:11:20 HHCDA004I opening dasd/smp004.14c readonly
00:11:20 HHCDA020I dasd/smp004.14c cyls=560 heads=30 tracks=16800 trklen=19456
00:11:20 HHCDA004I opening dasd/js2sp0.700 readonly
00:11:20 HHCDA020I dasd/js2sp0.700 cyls=555 heads=30 tracks=16650 trklen=19456
00:11:20 HHCDA004I opening dasd/dlicat.138 readonly
00:11:20 HHCDA020I dasd/dlicat.138 cyls=200 heads=20 tracks=4000 trklen=7680
00:11:20 HHCDA004I opening dasd/dlisys.139 readonly
00:11:20 HHCDA020I dasd/dlisys.139 cyls=200 heads=20 tracks=4000 trklen=7680
00:11:20 HHCDA004I opening dasd/dli000.13a readonly
00:11:20 HHCDA020I dasd/dli000.13a cyls=200 heads=20 tracks=4000 trklen=7680
00:11:20 HHCDA004I opening dasd/dli001.13b readonly
00:11:20 HHCDA020I dasd/dli001.13b cyls=200 heads=20 tracks=4000 trklen=7680
00:11:20 HHCDA004I opening dasd/dli002.13c readonly
00:11:20 HHCDA020I dasd/dli002.13c cyls=200 heads=20 tracks=4000 trklen=7680
00:11:20 HHCDA004I opening dasd/js3sp0.710 readonly
00:11:20 HHCDA020I dasd/js3sp0.710 cyls=555 heads=30 tracks=16650 trklen=19456
00:11:20 HHCDA004I opening dasd/js3res.711 readonly
00:11:20 HHCDA020I dasd/js3res.711 cyls=555 heads=30 tracks=16650 trklen=19456
00:11:20 HHCTE001I Console connection thread started: tid=00001A44, pid=4904
00:11:20 HHCTE003I Waiting for console connection on port 3270
00:11:20 HHCTA066I 0400: option 'level' accepted.
00:11:20 HHCTA066I 0401: option 'level' accepted.
00:11:20 HHCTA066I 0402: option 'level' accepted.
00:11:20 HHCTA066I 0403: option 'level' accepted.
00:11:20 HHCCP002I CPU0000 thread started: tid=00002C10, pid=4904, priority=0
00:11:20 HHCCP003I CPU0000 architecture mode S/370
00:11:20 HHCTT002I Timer thread started: tid=00000600, pid=4904, priority=-20
00:11:20 HHCPN001I Control panel thread started: tid=00000E20, pid=4904
00:11:20 HHCPN008I Script file processing started using file "conf/auto_run.rc"
00:11:20 HHCAO001I Hercules Automatic Operator thread started;
00:11:20 tid=000028BC, pri=0, pid=4904
00:11:20 devlist
00:11:20 0:000C 3505 127.0.0.1:3505 sockdev ascii trunc eof
00:11:20 (no one currently connected)
00:11:20 0:000D 3525 pch/pch00d.txt ascii crlf
00:11:20 0:000E 1403 prt/prt00e.txt crlf noclear print fcbck
00:11:20 0:000F 1403 prt/prt00f.txt crlf noclear print fcbck
00:11:20 0:001F 3215 *syscons cmdpref(/)
00:11:20 0:00C0 3270
00:11:20 0:00C1 3270
00:11:20 0:00C2 3270
00:11:20 0:00C7 3287
00:11:20 0:010C 3505 jcl/dummy eof
00:11:20 0:0131 2314 dasd/sort01.131 [200 cyls] open
00:11:20 0:0132 2314 dasd/sort02.132 [200 cyls] open
00:11:20 0:0133 2314 dasd/sort03.133 [200 cyls] open
00:11:20 0:0134 2314 dasd/sort04.134 [200 cyls] open
00:11:20 0:0135 2314 dasd/sort05.135 [200 cyls] open
00:11:20 0:0136 2314 dasd/sort06.136 [200 cyls] open
00:11:20 0:0138 2314 dasd/dlicat.138 [200 cyls] open
00:11:20 0:0139 2314 dasd/dlisys.139 [200 cyls] open
00:11:20 0:013A 2314 dasd/dli000.13a [200 cyls] open
00:11:20 0:013B 2314 dasd/dli001.13b [200 cyls] open
00:11:20 0:013C 2314 dasd/dli002.13c [200 cyls] open
00:11:20 0:0140 3350 dasd/work00.140 [560 cyls] open
00:11:20 0:0148 3350 dasd/mvsres.148 [560 cyls] open
00:11:20 0:0149 3350 dasd/smp001.149 [560 cyls] open
00:11:20 0:014A 3350 dasd/smp002.14a [560 cyls] open
00:11:20 0:014B 3350 dasd/smp003.14b [560 cyls] open
00:11:20 0:014C 3350 dasd/smp004.14c [560 cyls] open
00:11:20 0:0150 3330 dasd/start1.150 [808 cyls] open
00:11:20 0:0151 3330 dasd/spool0.151 [808 cyls] open
00:11:20 0:0152 3330 dasd/hasp00.152 [404 cyls] open
00:11:20 0:0160 3340 dasd/page00.160 [698 cyls] open
00:11:20 0:0161 3340 dasd/page01.161 [698 cyls] open
00:11:20 0:0162 3340 dasd/page02.162 [698 cyls] open
00:11:20 0:0170 3375 dasd/work01.170 [962 cyls] open
00:11:20 0:01A0 3380 dasd/work02.180 [886 cyls] open
00:11:20 0:01B0 3390 dasd/work03.190 [1114 cyls] open
00:11:20 0:01B1 3390 dasd/mvscat.191 [1114 cyls] open
00:11:20 0:01B2 3390 dasd/seasik.192 [1114 cyls] open
00:11:20 0:01B3 3390 dasd/mvssrc.193 [2226 cyls] open
00:11:20 0:01C7 3287
00:11:20 0:0240 3350 dasd/pub000.240 [560 cyls] open
00:11:20 0:0248 3350 dasd/mvsdlb.248 [560 cyls] open
00:11:20 0:02A0 3380 dasd/pub002.280 [1772 cyls] open
00:11:20 0:02B1 3390 dasd/tmptmp.2b1 [1114 cyls] open
00:11:20 0:02B2 3390 dasd/xmit90.2b2 [1114 cyls] open
00:11:20 0:030E 1403 log/hardcopy.log crlf noclear print fcbck
00:11:20 0:0340 3350 dasd/cbt000.340 [555 cyls] open
00:11:20 0:0341 3350 dasd/cbt001.341 [555 cyls] open
00:11:20 0:0342 3350 dasd/cbt002.342 [555 cyls] open
00:11:20 0:0343 3350 dasd/cbtcat.343 [555 cyls] open
00:11:20 0:0348 3350 dasd/src000.348 [555 cyls] open
00:11:20 0:0349 3350 dasd/src001.349 [555 cyls] open
00:11:20 0:034A 3350 dasd/src002.34a [555 cyls] open
00:11:20 0:034B 3350 dasd/srccat.34b [555 cyls] open
00:11:20 0:0400 3420 *
00:11:20 0:0401 3420 *
00:11:20 0:0402 3420 *
00:11:20 0:0403 3420 *
00:11:20 0:0700 3350 dasd/js2sp0.700 [555 cyls] open
00:11:20 0:0710 3350 dasd/js3sp0.710 [555 cyls] open
00:11:20 0:0711 3350 dasd/js3res.711 [555 cyls] open
00:11:20 logopt timestamp
00:11:20 HHCPN197I Log option set: TIMESTAMP
00:11:20 panrate 1000
00:11:20 # really need to wait for SVC120I, but if building MVS/380
00:11:20 # or some other stuffup with parms, need to trigger on an
00:11:20 # alternative. First one hit will clear targets.
00:11:20 # If we get a prompt for a device, cancel it
00:11:20 hao tgt IEF238D
00:11:20 HHCAO016I Target placed at index 0
00:11:20 hao cmd script conf/cancel.rc
00:11:20 HHCAO020I Command placed at index 0
00:11:20 hao tgt HASP395 DYNAMASK
00:11:20 HHCAO016I Target placed at index 1
00:11:20 hao cmd script conf/subjobs_slow.rc
00:11:20 HHCAO020I Command placed at index 1
00:11:20 hao tgt HASP373 SVC120I
00:11:20 HHCAO016I Target placed at index 2
00:11:20 hao cmd script conf/subjobs_fast.rc
00:11:20 HHCAO020I Command placed at index 2
00:11:20 hao tgt HASP436 REPLY
00:11:20 HHCAO016I Target placed at index 3
00:11:20 hao cmd script conf/replyy.rc
00:11:20 HHCAO020I Command placed at index 3
00:11:20 devinit 402 tapes/mftopc.het
00:11:20 HHCTA004I 0402: tapes/mftopc.het is a Hercules Emulated Tape file
00:11:20 HHCPN098I Device 0:0402 initialized
00:11:20 devinit 403 tapes/awstap.aws
00:11:20 HHCTA004I 0403: tapes/awstap.aws is a Hercules Emulated Tape file
00:11:20 HHCPN098I Device 0:0403 initialized
00:11:20 # co will give you a cold start of JES2 which is useful in
00:11:20 # automated runs
00:11:20 /(001F) r 00,clpa,cmd=co
00:11:20 #/r 00,clpa
00:11:20 ipl 148
00:11:20 HHCPN013I EOF reached on SCRIPT file. Processing complete.
00:11:20 IEA101A SPECIFY SYSTEM PARMS FOR MVS/380 1.2 v03.8 TK3+
00:11:20 HHCCD001I Readahead thread 1 started: tid=00002918, pid=4904
00:11:20 HHCCD001I Readahead thread 2 started: tid=000018BC, pid=4904
00:11:20 HHCCD002I Writer thread 1 started: tid=00002518, pid=4904
00:11:20 HHCCD003I Garbage collector thread started: tid=00002ED8, pid=4904
00:11:20 IEA940I THE FOLLOWING PAGE DATA SETS ARE IN USE
00:11:20 PLPA ... SYS1.PAGELPA
00:11:20 COMMON . SYS1.PAGECSA
00:11:20 DUPLEX . SYS1.DUPLEX
00:11:20 LOCAL .. SYS1.PAGEL01
00:11:20 LOCAL .. SYS1.PAGEL02
00:11:20 LOCAL .. SYS1.PAGEL03
00:11:20 HHCCD002I Writer thread 2 started: tid=00002F90, pid=4904
00:11:22 *IEE362A SMF ENTER DUMP FOR SYS1.MANX ON MVSRES
00:11:22 IEE360I SMF NOW RECORDING ON SYS1.MANY ON MVSRES TIME=13.11.22
00:11:22 IGF992I MIH INIT COMPLETE, PRI=000300, SEC=000015
00:11:22 IEF677I WARNING MESSAGE(S) FOR JOB JES2 ISSUED
00:11:22 *00 $HASP436 REPLY Y OR N TO CONFIRM CHECKPOINT RECORD CHANGE
00:11:22 HHCAO003I Firing command: 'script conf/replyy.rc'
00:11:22 script conf/replyy.rc
00:11:22 /(001F) reply 00,y
00:11:22 HHCPN013I EOF reached on SCRIPT file. Processing complete.
00:11:22 IEE600I REPLY TO 00 IS;SUPPRESSED
00:11:22 $HASP493 JES2 COLD-START IS IN PROGRESS
00:11:22 $HASP412 MAXIMUM OF 1 READER(S) EXCEEDED
00:11:23 13.11.23 IEE041I THE SYSTEM LOG IS NOW ACTIVE
00:11:23 13.11.23 IEE302I 00E ONLINE
00:11:23 13.11.23 IEE302I 00F ONLINE
00:11:23 13.11.23 IEE313I 30E UNIT REF INVALID
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 IEE450I 13.11.23 UNIT STATUS 161
00:11:23 UNIT TYPE STATUS VOLSER VOLSTATE UNIT TYPE STATUS VOLSER VOLSTATE
00:11:23 400 3400 O /REMOV 401 3400 O /REMOV
00:11:23 402 3400 O /REMOV
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 $HASP160 PRINTER1 INACTIVE - CLASS=AP
00:11:23 13.11.23 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:23 13.11.23 $HASP160 PUNCH1 INACTIVE - CLASS=B
00:11:23 13.11.23 STC 2 $HASP100 INIT ON STCINRDR
00:11:23 13.11.23 STC 2 $HASP373 INIT STARTED
00:11:23 13.11.23 STC 2 IEF403I INIT - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 3 $HASP100 INIT ON STCINRDR
00:11:23 13.11.23 STC 3 $HASP373 INIT STARTED
00:11:23 13.11.23 STC 3 IEF403I INIT - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 4 $HASP100 INIT ON STCINRDR
00:11:23 13.11.23 STC 4 $HASP373 INIT STARTED
00:11:23 13.11.23 STC 4 IEF403I INIT - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 5 $HASP100 INIT ON STCINRDR
00:11:23 13.11.23 STC 5 $HASP373 INIT STARTED
00:11:23 13.11.23 STC 5 IEF403I INIT - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 6 $HASP100 INIT ON STCINRDR
00:11:23 13.11.23 STC 6 $HASP373 INIT STARTED
00:11:23 13.11.23 STC 6 IEF403I INIT - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 7 $HASP100 INIT ON STCINRDR
00:11:23 13.11.23 STC 7 $HASP373 INIT STARTED
00:11:23 13.11.23 STC 7 IEF403I INIT - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 8 $HASP100 INIT ON STCINRDR
00:11:23 13.11.23 STC 8 $HASP373 INIT STARTED
00:11:23 13.11.23 STC 8 IEF403I INIT - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 9 $HASP100 SVC120I ON STCINRDR
00:11:23 13.11.23 STC 9 $HASP373 SVC120I STARTED
00:11:23 HHCAO003I Firing command: 'script conf/subjobs_fast.rc'
00:11:23 script conf/subjobs_fast.rc
00:11:23 # Now we know that SVC120I has started. But due to some
00:11:23 # weird pausing, it may get locked out. So clear out
00:11:23 # other triggers and wait on this
00:11:23 hao clear
00:11:23 HHCAO022I All automatic operation rules cleared
00:11:23 hao tgt HASP250 SVC120I
00:11:23 HHCAO016I Target placed at index 0
00:11:23 hao cmd script conf/subjobs.rc
00:11:23 HHCAO020I Command placed at index 0
00:11:23 HHCPN013I EOF reached on SCRIPT file. Processing complete.
00:11:23 13.11.23 STC 9 IEF403I SVC120I - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 10 $HASP100 DYNABLDL ON STCINRDR
00:11:23 13.11.23 STC 10 $HASP373 DYNABLDL STARTED
00:11:23 13.11.23 STC 10 IEF403I DYNABLDL - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 11 $HASP100 DYNAMASK ON STCINRDR
00:11:23 13.11.23 STC 11 $HASP373 DYNAMASK STARTED
00:11:23 13.11.23 STC 11 IEF403I DYNAMASK - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 12 $HASP100 BSPPILOT ON STCINRDR
00:11:23 13.11.23 STC 12 $HASP373 BSPPILOT STARTED
00:11:23 13.11.23 STC 12 IEF403I BSPPILOT - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 13 $HASP100 BSPSETPF ON STCINRDR
00:11:23 13.11.23 STC 13 $HASP373 BSPSETPF STARTED
00:11:23 13.11.23 STC 13 IEF403I BSPSETPF - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 14 $HASP100 LOGRECI ON STCINRDR
00:11:23 13.11.23 STC 14 $HASP373 LOGRECI STARTED
00:11:23 13.11.23 STC 14 IEF403I LOGRECI - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 15 $HASP100 NET ON STCINRDR
00:11:23 13.11.23 $HASP309 INIT 1 INACTIVE ******** C=A
00:11:23 13.11.23 $HASP309 INIT 2 INACTIVE ******** C=BA
00:11:23 13.11.23 STC 15 $HASP373 NET STARTED
00:11:23 13.11.23 STC 15 IEF403I NET - STARTED - TIME=13.11.23
00:11:23 13.11.23 $HASP309 INIT 3 INACTIVE ******** C=CBA
00:11:23 13.11.23 $HASP309 INIT 4 INACTIVE ******** C=SHB
00:11:23 13.11.23 $HASP309 INIT 5 INACTIVE ******** C=SBA
00:11:23 13.11.23 $HASP309 INIT 6 INACTIVE ******** C=S
00:11:23 13.11.23 $HASP309 INIT 7 INACTIVE ******** C=E
00:11:23 13.11.23 STC 9 BSPGM39E - Hercules and MVS 380 mods required
00:11:23 13.11.23 STC 9 IEF404I SVC120I - ENDED - TIME=13.11.23
00:11:23 13.11.23 STC 9 $HASP395 SVC120I ENDED
00:11:23 13.11.23 STC 9 $HASP150 SVC120I ON PRINTER2 41 LINES
00:11:23 13.11.23 STC 9 *$HASP190 SVC120I SETUP -- PRINTER2 -- F = 0001 -- C = 6 -- T = SN
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:23 13.11.23 STC 9 $HASP250 SVC120I IS PURGED
00:11:23 HHCAO003I Firing command: 'script conf/subjobs.rc'
00:11:23 script conf/subjobs.rc
00:11:23 hao clear
00:11:23 HHCAO022I All automatic operation rules cleared
00:11:23 # Every job gets an NL tape available as input, containing
00:11:23 # some binary of unknown contents, most likely needing to
00:11:23 # be read as RECFM=U, but RECFM=FB and even RECFM=V are also
00:11:23 # possible.
00:11:23 #
00:11:23 # The job also gets an SL tape available for output, and
00:11:23 # again, any type of content can be written to it, and
00:11:23 # with a bit of luck, hetget will be able to extract the
00:11:23 # data you are looking for.
00:11:23 #
00:11:23 # And finally the job gets an SL AWS tape available for
00:11:23 # input and/or output should you wish to construct a
00:11:23 # special tape. Tape must be called AWSTAP. User should
00:11:23 # back the tape up before submitting it, because it will
00:11:23 # be overwritten and anything could go wrong. AWS is
00:11:23 # expected to be exceptional use of this procedure anyway
00:11:23 #
00:11:23 # Only the NL tape needs an explicit mount. The SL tapes
00:11:23 # are premounted before IPL
00:11:23 hao tgt HASP250 MOUNT
00:11:23 HHCAO016I Target placed at index 0
00:11:23 hao cmd script conf/subjobs2.rc
00:11:23 HHCAO020I Command placed at index 0
00:11:23 /(001F) M 401,VOL=(NL,PCTOMF)
00:11:23 HHCPN013I EOF reached on SCRIPT file. Processing complete.
00:11:23 13.11.23 STC 16 $HASP100 MOUNT ON STCINRDR
00:11:23 13.11.23 STC 16 $HASP373 MOUNT STARTED
00:11:23 13.11.23 STC 16 IEF403I MOUNT - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 16 *IEF233A M 401,PCTOMF,,MOUNT,401
00:11:23 13.11.23 STC 10 DYNABLDL STARTED
00:11:23 13.11.23 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
00:11:23 13.11.23 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
00:11:23 13.11.23 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
00:11:23 13.11.23 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
00:11:23 13.11.23 STC 15 IST025I BLDL FAILED FOR IEDIAK IN VTAMLIB
00:11:23 13.11.23 STC 15 IST025I BLDL FAILED FOR IEDIAK IN VTAMLIB
00:11:23 13.11.23 STC 10 IEF404I DYNABLDL - ENDED - TIME=13.11.23
00:11:23 13.11.23 STC 10 $HASP395 DYNABLDL ENDED
00:11:23 13.11.23 STC 10 $HASP150 DYNABLDL ON PRINTER2 21 LINES
00:11:23 13.11.23 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:23 13.11.23 STC 10 $HASP250 DYNABLDL IS PURGED
00:11:23 13.11.23 STC 15 IST110I NETWORK SOLICITOR STARTED
00:11:23 13.11.23 STC 15 IST093I APPLJRP ACTIVE
00:11:23 13.11.23 STC 15 IST093I APPLPIES ACTIVE
00:11:23 13.11.23 STC 15 IST093I APPLPIAD ACTIVE
00:11:23 13.11.23 STC 15 IST093I APPLTSO ACTIVE
00:11:23 13.11.23 STC 15 IST093I APPLTEST ACTIVE
00:11:23 13.11.23 STC 15 IST093I LCLMAJRP ACTIVE
00:11:23 13.11.23 STC 15 IST093I LCLMAJ00 ACTIVE
00:11:23 13.11.23 STC 17 $HASP100 TSO ON STCINRDR
00:11:23 13.11.23 STC 17 $HASP373 TSO STARTED
00:11:23 13.11.23 STC 17 IEF403I TSO - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 18 $HASP100 JRP ON STCINRDR
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 STC 15 IST020I VTAM INITIALIZATION COMPLETE
00:11:23 13.11.23 STC 18 $HASP373 JRP STARTED
00:11:23 13.11.23 STC 18 IEF403I JRP - STARTED - TIME=13.11.23
00:11:23 13.11.23 STC 15 IEA000I 0C1,IOE,05,0200,400000000001,,,NET ,13.11.23
00:11:23 13.11.23 STC 15 IEA000I 0C0,IOE,05,0200,400000000001,,,NET ,13.11.23
00:11:23 13.11.23 STC 15 IEA000I 0C2,IOE,05,0200,400000000001,,,NET ,13.11.23
00:11:23 13.11.23 STC 11 DMSK00I DYNAMASK DONE ****
00:11:23 13.11.23 STC 11 DMSK06I START
00:11:23 13.11.23 STC 11 IEF404I DYNAMASK - ENDED - TIME=13.11.23
00:11:23 13.11.23 STC 11 $HASP395 DYNAMASK ENDED
00:11:23 13.11.23 STC 11 $HASP150 DYNAMASK ON PRINTER2 30 LINES
00:11:23 13.11.23 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:23 13.11.23 STC 11 $HASP250 DYNAMASK IS PURGED
00:11:23 13.11.23 STC 13 BSPSP91I - Parms passed: NOREPLYU
00:11:23 13.11.23 STC 13 BSPSP93I - PFK definitions will be updated in memory
00:11:23 13.11.23 STC 13 BSPSP22I - Dataset processed: SYS1.PARMLIB
00:11:23 13.11.23 STC 13 BSPSP23I - on volume MVSRES
00:11:23 13.11.23 STC 13 BSPSP21I - Member being processed: SETPFK01
00:11:23 13.11.23 STC 13 +BSPSP98I - Member processed, LASTCC=0000
00:11:23 13.11.23 STC 13 +BSPSP21I - Member being processed: SETPFK02
00:11:23 13.11.23 STC 13 +BSPSP98I - Member processed, LASTCC=0000
00:11:23 13.11.23 STC 13 +BSPSP99I - End of processing, MAXRC=0000
00:11:23 13.11.23 STC 13 IEF404I BSPSETPF - ENDED - TIME=13.11.23
00:11:23 13.11.23 STC 13 $HASP395 BSPSETPF ENDED
00:11:23 13.11.23 STC 13 $HASP150 BSPSETPF ON PRINTER2 34 LINES
00:11:23 13.11.23 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:23 13.11.23 STC 13 $HASP250 BSPSETPF IS PURGED
00:11:23 13.11.23 STC 14 IFC001I D=3350 N=0B F=01AB0000 L=01AC0005 S=01AB000002 DIP COMPLETE
00:11:23 13.11.23 STC 14 IEF404I LOGRECI - ENDED - TIME=13.11.23
00:11:23 13.11.23 STC 14 $HASP395 LOGRECI ENDED
00:11:23 13.11.23 STC 14 $HASP150 LOGRECI ON PRINTER2 20 LINES
00:11:23 13.11.23 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:23 13.11.23 STC 14 $HASP250 LOGRECI IS PURGED
00:11:23 13.11.23 STC 16 IEF404I MOUNT - ENDED - TIME=13.11.23
00:11:23 13.11.23 STC 16 $HASP395 MOUNT ENDED
00:11:23 13.11.23 STC 16 $HASP150 MOUNT ON PRINTER2 18 LINES
00:11:23 13.11.23 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:23 13.11.23 STC 16 $HASP250 MOUNT IS PURGED
00:11:23 HHCAO003I Firing command: 'script conf/subjobs2.rc'
00:11:23 script conf/subjobs2.rc
00:11:23 hao clear
00:11:23 HHCAO022I All automatic operation rules cleared
00:11:23 # If we get a prompt for a device, cancel it
00:11:23 hao tgt IEF238D
00:11:23 HHCAO016I Target placed at index 0
00:11:23 hao cmd script conf/cancel.rc
00:11:23 HHCAO020I Command placed at index 0
00:11:23 # If we get a prompt for a catalogue password, answer it
00:11:23 hao tgt IEC301A
00:11:23 HHCAO016I Target placed at index 1
00:11:23 hao cmd script conf/secret.rc
00:11:23 HHCAO020I Command placed at index 1
00:11:23 devinit 401 tapes/pctomf.tdf
00:11:23 HHCTA004I 0401: tapes/pctomf.tdf is a Optical Media Attachment (OMA) tape
00:11:23 HHCPN098I Device 0:0401 initialized
00:11:23 # When we see TERMHERC get purged, our job is done
00:11:23 hao tgt HASP373 TERMHERC
00:11:23 HHCAO016I Target placed at index 2
00:11:23 hao cmd script conf/termherc.rc
00:11:23 HHCAO020I Command placed at index 2
00:11:23 # Now submit the job
00:11:23 devinit 00c jcl/hercauto.jcl eof
00:11:23 HHCSD007I Device 000C unbound from socket 127.0.0.1:3505
00:11:23 HHCSD022I Socketdevice listener thread terminated
00:11:23 HHCPN098I Device 0:000C initialized
00:11:23 HHCPN013I EOF reached on SCRIPT file. Processing complete.
00:11:23 13.11.23 JOB 1 $HASP100 HEXDUMP ON READER1
00:11:23 13.11.23 JOB 2 $HASP100 TERMHERC ON READER1
00:11:23 13.11.23 JOB 1 $HASP373 HEXDUMP STARTED - INIT 3 - CLASS C - SYS BSP1
00:11:23 13.11.23 JOB 1 IEF403I HEXDUMP - STARTED - TIME=13.11.23
00:11:23 13.11.23 JOB 1 *IEF233A M 401,PCTOMF,,HEXDUMP,HEXDUMP
00:11:23 13.11.23 STC 17 IKT007I TCAS ACCEPTING LOGONS
00:11:23 13.11.23 STC 17 IKT005I TCAS IS INITIALIZED
00:11:23 13.11.23 STC 18 JRPI101 INITIALIZATION COMPLETE
00:11:23 13.11.23 STC 18 *01 JRP100I - ENTER ICLOSE TO SHUT DOWN
00:11:23 13.11.23 JOB 1 IEC705I TAPE ON 402,MFTOPC,SL,6250 BPI,HEXDUMP,HEXDUMP
00:11:23 13.11.23 JOB 1 IEF234E K 402,MFTOPC,PVT,HEXDUMP,HEXDUMP
00:11:23 13.11.23 JOB 1 IEFACTRT - Stepname Procstep Program Retcode
00:11:23 13.11.23 JOB 1 HEXDUMP HEXDUMP HEXDUMP RC= 0000
00:11:23 13.11.23 JOB 1 IEF404I HEXDUMP - ENDED - TIME=13.11.23
00:11:23 13.11.23 JOB 1 $HASP395 HEXDUMP ENDED
00:11:23 13.11.23 JOB 1 $HASP150 HEXDUMP ON PRINTER1 55 LINES
00:11:23 13.11.23 JOB 1 *$HASP190 HEXDUMP SETUP -- PRINTER1 -- F = 0001 -- C = 6 -- T = SN
00:11:23 13.11.23 $HASP000 OK
00:11:23 13.11.23 JOB 2 $HASP373 TERMHERC STARTED - INIT 3 - CLASS C - SYS BSP1
00:11:23 HHCAO003I Firing command: 'script conf/termherc.rc'
00:11:23 script conf/termherc.rc
00:11:23 # We do an unnecessary 2-stage terminate, first triggering
00:11:23 # on the start message, then triggering on the purged
00:11:23 # message, to overcome an apparent bug in hercules which
00:11:23 # causes it to sometimes trigger on the wrong jobname.
00:11:23 hao clear
00:11:23 HHCAO022I All automatic operation rules cleared
00:11:23 hao tgt HASP250 TERMHERC
00:11:23 HHCAO016I Target placed at index 0
00:11:23 hao cmd script conf/termherc2.rc
00:11:23 HHCAO020I Command placed at index 0
00:11:23 HHCPN013I EOF reached on SCRIPT file. Processing complete.
00:11:23 13.11.23 JOB 2 IEF403I TERMHERC - STARTED - TIME=13.11.23
00:11:23 13.11.23 $HASP160 PRINTER1 INACTIVE - CLASS=AP
00:11:23 13.11.23 JOB 1 $HASP250 HEXDUMP IS PURGED
00:11:23 13.11.23 JOB 2 IEFACTRT - Stepname Procstep Program Retcode
00:11:23 13.11.23 JOB 2 TERMHERC S1 IEBGENER RC= 0000
00:11:23 13.11.23 JOB 2 IEF404I TERMHERC - ENDED - TIME=13.11.23
00:11:23 13.11.23 JOB 2 $HASP395 TERMHERC ENDED
00:11:23 13.11.23 $HASP309 INIT 3 INACTIVE ******** C=CBA
00:11:23 13.11.23 JOB 2 $HASP150 TERMHERC ON PRINTER2 44 LINES
00:11:23 13.11.23 JOB 2 $HASP150 TERMHERC ON PRINTER1 1 LINE
00:11:23 13.11.23 $HASP160 PRINTER1 INACTIVE - CLASS=AP
00:11:23 13.11.23 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:23 13.11.23 JOB 2 $HASP250 TERMHERC IS PURGED
00:11:23 HHCAO003I Firing command: 'script conf/termherc2.rc'
00:11:23 script conf/termherc2.rc
00:11:23 quit
00:11:23 HHCIN900I Begin Hercules shutdown
00:11:23 HHCIN901I Releasing configuration
00:11:23 HHCCP008I CPU0000 thread ended: tid=00002C10, pid=4904
00:11:23 HHCCF047I Subchannel 0:0000 detached
00:11:23 HHCCF047I Subchannel 0:0001 detached
00:11:23 HHCCF047I Subchannel 0:0002 detached
00:11:23 HHCCF047I Subchannel 0:0003 detached
00:11:23 HHCCF047I Subchannel 0:0004 detached
00:11:23 HHCTT003I Timer thread ended
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD211I readaheads misses
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 19298902 4% 35 1125 25 34 1005 1973
00:11:23 HHCCD214I 160 29
00:11:23 HHCCD215I dasd/mvsres.148
00:11:23 HHCCD216I [0] 15179178 0% 1 ro 940 0 17
00:11:23 HHCCD217I shadow/mvsres_*.148
00:11:23 HHCCD218I [1] 4119724 16% 34 185 25 17
00:11:23 HHCCF047I Subchannel 0:0005 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 35424 0% 1 1 0 1 0 1
00:11:23 HHCCD215I dasd/sort01.131
00:11:23 HHCCD216I [0] 34336 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/sort01_*.131
00:11:23 HHCCD218I [1] 1088 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:0006 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 35424 0% 1 1 0 1 0 1
00:11:23 HHCCD215I dasd/sort02.132
00:11:23 HHCCD216I [0] 34336 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/sort02_*.132
00:11:23 HHCCD218I [1] 1088 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:0007 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 35424 0% 1 1 0 1 0 1
00:11:23 HHCCD215I dasd/sort03.133
00:11:23 HHCCD216I [0] 34336 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/sort03_*.133
00:11:23 HHCCD218I [1] 1088 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:0008 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 35424 0% 1 1 0 1 0 1
00:11:23 HHCCD215I dasd/sort04.134
00:11:23 HHCCD216I [0] 34336 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/sort04_*.134
00:11:23 HHCCD218I [1] 1088 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:0009 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 35424 0% 1 1 0 1 0 1
00:11:23 HHCCD215I dasd/sort05.135
00:11:23 HHCCD216I [0] 34336 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/sort05_*.135
00:11:23 HHCCD218I [1] 1088 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:000A detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 35424 0% 1 1 0 1 0 1
00:11:23 HHCCD215I dasd/sort06.136
00:11:23 HHCCD216I [0] 34336 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/sort06_*.136
00:11:23 HHCCD218I [1] 1088 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:000B detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 52422417 2% 45 1 0 2 0 1
00:11:23 HHCCD215I dasd/work00.140
00:11:23 HHCCD216I [0] 141963 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/work00_*.140
00:11:23 HHCCD218I [1] 52280454 2% 44 0 0 1
00:11:23 HHCCF047I Subchannel 0:000C detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 5421226 11% 4 1 0 1 0 1
00:11:23 HHCCD215I dasd/hasp00.152
00:11:23 HHCCD216I [0] 5421226 11% 4 rw 1 0 1
00:11:23 HHCCF047I Subchannel 0:000D detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD211I readaheads misses
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 14314713 39% 254 1832 1369 8 1149 2362
00:11:23 HHCCD214I 619 52
00:11:23 HHCCD215I dasd/page00.160
00:11:23 HHCCD216I [0] 14314713 39% 254 rw 1832 1369 8
00:11:23 HHCCF047I Subchannel 0:000E detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD211I readaheads misses
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 3770781 12% 21 46 1166 32 37 56
00:11:23 HHCCD214I 27 1
00:11:23 HHCCD215I dasd/page01.161
00:11:23 HHCCD216I [0] 3770781 12% 21 rw 46 1166 32
00:11:23 HHCCF047I Subchannel 0:000F detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD211I readaheads misses
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 3373857 7% 39 39 35 1 32 52
00:11:23 HHCCD214I 19 3
00:11:23 HHCCD215I dasd/page02.162
00:11:23 HHCCD216I [0] 3373857 7% 39 rw 39 35 1
00:11:23 HHCCF047I Subchannel 0:0010 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 57202932 1% 14 1 0 1 0 1
00:11:23 HHCCD215I dasd/work01.170
00:11:23 HHCCD216I [0] 57202932 1% 14 rw 1 0 1
00:11:23 HHCCF047I Subchannel 0:0011 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 66242054 1% 300 1 0 2 0 1
00:11:23 HHCCD215I dasd/work02.180
00:11:23 HHCCD216I [0] 113799 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/work02_*.180
00:11:23 HHCCD218I [1] 66128255 1% 299 0 0 1
00:11:23 HHCCF047I Subchannel 0:0012 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 56355632 1% 158 1 0 2 0 1
00:11:23 HHCCD215I dasd/work03.190
00:11:23 HHCCD216I [0] 142257 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/work03_*.190
00:11:23 HHCCD218I [1] 56213375 2% 157 0 0 1
00:11:23 HHCCF047I Subchannel 0:0013 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 17037777 9% 16 4 0 3 0 4
00:11:23 HHCCD215I dasd/mvscat.191
00:11:23 HHCCD216I [0] 3658727 0% 1 ro 3 0 2
00:11:23 HHCCD217I shadow/mvscat_*.191
00:11:23 HHCCD218I [1] 13379050 11% 15 1 0 1
00:11:23 HHCCF047I Subchannel 0:0014 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 103500159 17% 1297 1 0 2 0 1
00:11:23 HHCCD215I dasd/seasik.192
00:11:23 HHCCD216I [0] 16164960 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/seasik_*.192
00:11:23 HHCCD218I [1] 87335199 20% 1297 0 0 1
00:11:23 HHCCF047I Subchannel 0:0015 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 168333900 4% 5454 1 0 1 0 1
00:11:23 HHCCD215I dasd/mvssrc.193
00:11:23 HHCCD216I [0] 168333900 4% 5454 rw 1 0 1
00:11:23 HHCCF047I Subchannel 0:0016 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD211I readaheads misses
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 44516465 2% 19 38 0 9 36 68
00:11:23 HHCCD214I 6 3
00:11:23 HHCCD215I dasd/pub000.240
00:11:23 HHCCD216I [0] 7591138 3% 1 ro 12 0 4
00:11:23 HHCCD217I shadow/pub000_*.240
00:11:23 HHCCD218I [1] 36925327 2% 18 26 0 5
00:11:23 HHCCF047I Subchannel 0:0017 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 25896197 1% 7 5 2 5 1 6
00:11:23 HHCCD215I dasd/mvsdlb.248
00:11:23 HHCCD216I [0] 25471539 0% 1 ro 3 0 3
00:11:23 HHCCD217I shadow/mvsdlb_*.248
00:11:23 HHCCD218I [1] 424658 64% 6 2 2 2
00:11:23 HHCCF047I Subchannel 0:0018 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 100064666 8% 539 1 0 2 0 1
00:11:23 HHCCD215I dasd/pub002.280
00:11:23 HHCCD216I [0] 2171954 29% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/pub002_*.280
00:11:23 HHCCD218I [1] 97892712 8% 538 0 0 1
00:11:23 HHCCF047I Subchannel 0:0019 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 143545 0% 1 1 0 1 0 1
00:11:23 HHCCD215I dasd/tmptmp.2b1
00:11:23 HHCCD216I [0] 142257 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/tmptmp_*.2b1
00:11:23 HHCCD218I [1] 1288 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:001A detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 143545 0% 1 1 0 1 0 1
00:11:23 HHCCD215I dasd/xmit90.2b2
00:11:23 HHCCD216I [0] 142257 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/xmit90_*.2b2
00:11:23 HHCCD218I [1] 1288 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:001B detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 6099280 0% 0 1 0 1 0 1
00:11:23 HHCCD215I dasd/start1.150
00:11:23 HHCCD216I [0] 6098016 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/start1_*.150
00:11:23 HHCCD218I [1] 1264 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:001C detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 4595678 0% 0 1 0 1 0 1
00:11:23 HHCCD215I dasd/spool0.151
00:11:23 HHCCD216I [0] 4594414 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/spool0_*.151
00:11:23 HHCCD218I [1] 1264 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:001D detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 50622559 0% 0 1 0 1 0 1
00:11:23 HHCCD215I dasd/cbt000.340
00:11:23 HHCCD216I [0] 50621271 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/cbt000_*.340
00:11:23 HHCCD218I [1] 1288 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:001E detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 53836805 0% 0 1 0 1 0 1
00:11:23 HHCCD215I dasd/cbt001.341
00:11:23 HHCCD216I [0] 53835517 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/cbt001_*.341
00:11:23 HHCCD218I [1] 1288 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:001F detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 46082980 0% 0 1 0 1 0 1
00:11:23 HHCCD215I dasd/cbt002.342
00:11:23 HHCCD216I [0] 46081692 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/cbt002_*.342
00:11:23 HHCCD218I [1] 1288 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:0020 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 27241782 0% 0 1 0 1 0 1
00:11:23 HHCCD215I dasd/cbtcat.343
00:11:23 HHCCD216I [0] 27240494 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/cbtcat_*.343
00:11:23 HHCCD218I [1] 1288 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:0021 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 46003602 0% 0 1 0 1 0 1
00:11:23 HHCCD215I dasd/src000.348
00:11:23 HHCCD216I [0] 46002314 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/src000_*.348
00:11:23 HHCCD218I [1] 1288 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:0022 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 45707725 0% 0 1 0 1 0 1
00:11:23 HHCCD215I dasd/src001.349
00:11:23 HHCCD216I [0] 45706437 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/src001_*.349
00:11:23 HHCCD218I [1] 1288 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:0023 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 44403653 0% 0 1 0 1 0 1
00:11:23 HHCCD215I dasd/src002.34a
00:11:23 HHCCD216I [0] 44402365 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/src002_*.34a
00:11:23 HHCCD218I [1] 1288 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:0024 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 6321674 0% 1 1 0 1 0 1
00:11:23 HHCCD215I dasd/srccat.34b
00:11:23 HHCCD216I [0] 6310767 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/srccat_*.34b
00:11:23 HHCCD218I [1] 10907 7% 1 0 0 0
00:11:23 HHCCF047I Subchannel 0:0025 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 1118801 11% 2 1 0 2 0 1
00:11:23 HHCCD215I dasd/smp001.149
00:11:23 HHCCD216I [0] 774654 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/smp001_*.149
00:11:23 HHCCD218I [1] 344147 38% 2 0 0 1
00:11:23 HHCCF047I Subchannel 0:0026 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 1621663 24% 12 1 0 2 0 1
00:11:23 HHCCD215I dasd/smp002.14a
00:11:23 HHCCD216I [0] 856740 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/smp002_*.14a
00:11:23 HHCCD218I [1] 764923 51% 12 0 0 1
00:11:23 HHCCF047I Subchannel 0:0027 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 1077383 19% 3 1 0 2 0 1
00:11:23 HHCCD215I dasd/smp003.14b
00:11:23 HHCCD216I [0] 592555 0% 0 ro 1 0 1
00:11:23 HHCCD217I shadow/smp003_*.14b
00:11:23 HHCCD218I [1] 484828 42% 3 0 0 1
00:11:23 HHCCF047I Subchannel 0:0028 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 3437923 36% 4 1 0 2 0 1
00:11:23 HHCCD215I dasd/smp004.14c
00:11:23 HHCCD216I [0] 2916431 35% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/smp004_*.14c
00:11:23 HHCCD218I [1] 521492 41% 3 0 0 1
00:11:23 HHCCF047I Subchannel 0:0029 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD211I readaheads misses
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 9850472 1% 140 116 106 6 723 811
00:11:23 HHCCD214I 30 14
00:11:23 HHCCD215I dasd/js2sp0.700
00:11:23 HHCCD216I [0] 142291 0% 1 ro 0 0 1
00:11:23 HHCCD217I shadow/js2sp0_*.700
00:11:23 HHCCD218I [1] 9708181 1% 139 116 106 5
00:11:23 HHCCF047I Subchannel 0:002A detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 715081 0% 1 1 0 2 0 1
00:11:23 HHCCD215I dasd/dlicat.138
00:11:23 HHCCD216I [0] 36630 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/dlicat_*.138
00:11:23 HHCCD218I [1] 678451 0% 0 0 0 1
00:11:23 HHCCF047I Subchannel 0:002B detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 880289 0% 1 1 0 2 0 1
00:11:23 HHCCD215I dasd/dlisys.139
00:11:23 HHCCD216I [0] 36630 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/dlisys_*.139
00:11:23 HHCCD218I [1] 843659 0% 0 0 0 1
00:11:23 HHCCF047I Subchannel 0:002C detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 43495 0% 1 1 0 2 0 1
00:11:23 HHCCD215I dasd/dli000.13a
00:11:23 HHCCD216I [0] 36630 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/dli000_*.13a
00:11:23 HHCCD218I [1] 6865 0% 0 0 0 1
00:11:23 HHCCF047I Subchannel 0:002D detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 46911 0% 1 1 0 2 0 1
00:11:23 HHCCD215I dasd/dli001.13b
00:11:23 HHCCD216I [0] 36630 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/dli001_*.13b
00:11:23 HHCCD218I [1] 10281 0% 0 0 0 1
00:11:23 HHCCF047I Subchannel 0:002E detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 37718 0% 1 1 0 1 0 1
00:11:23 HHCCD215I dasd/dli002.13c
00:11:23 HHCCD216I [0] 36630 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/dli002_*.13c
00:11:23 HHCCD218I [1] 1088 0% 0 0 0 0
00:11:23 HHCCF047I Subchannel 0:002F detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 1233964 0% 1 1 0 2 0 1
00:11:23 HHCCD215I dasd/js3sp0.710
00:11:23 HHCCD216I [0] 141965 0% 1 ro 1 0 1
00:11:23 HHCCD217I shadow/js3sp0_*.710
00:11:23 HHCCD218I [1] 1091999 0% 0 0 0 1
00:11:23 HHCCF047I Subchannel 0:0030 detached
00:11:23 HHCCD210I size free nbr st reads writes l2reads hits switches
00:11:23 HHCCD212I --------------------------------------------------------------------
00:11:23 HHCCD213I [*] 951745 0% 2 1 0 2 0 1
00:11:23 HHCCD215I dasd/js3res.711
00:11:23 HHCCD216I [0] 142093 0% 2 ro 1 0 1
00:11:23 HHCCD217I shadow/js3res_*.711
00:11:23 HHCCD218I [1] 809652 0% 0 0 0 1
00:11:23 HHCCD011I Readahead thread 2 stopping: tid=000018BC, pid=4904
00:11:23 HHCCD011I Readahead thread 1 stopping: tid=00002918, pid=4904
00:11:23 HHCCD013I Garbage collector thread stopping: tid=00002ED8, pid=4904
00:11:23 HHCCD012I Writer thread 2 stopping: tid=00002F90, pid=4904
00:11:23 HHCCD012I Writer thread 1 stopping: tid=00002518, pid=4904
00:11:23 HHCCF047I Subchannel 0:0031 detached
00:11:23 HHCCF047I Subchannel 0:0032 detached
00:11:23 HHCCF047I Subchannel 0:0033 detached
00:11:23 HHCCF047I Subchannel 0:0034 detached
00:11:23 HHCCF047I Subchannel 0:0035 detached
00:11:23 HHCCF047I Subchannel 0:0036 detached
00:11:23 HHCCF047I Subchannel 0:0037 detached
00:11:23 HHCTE004I Console connection thread terminated
00:11:23 HHCCF047I Subchannel 0:0038 detached
00:11:23 HHCCF047I Subchannel 0:0039 detached
00:11:23 HHCCF047I Subchannel 0:003A detached
00:11:23 HHCCF047I Subchannel 0:003B detached
00:11:23 HHCCF047I Subchannel 0:003C detached
00:11:23 HHCIN902I Configuration release complete
00:11:23 HHCIN903I Calling termination routines
00:11:23 HHCHD900I Begin shutdown sequence
00:11:23 HHCHD901I Calling panel_cleanup
00:11:23 HHCHD902I panel_cleanup complete
00:11:23 HHCHD901I Calling console_shutdown
00:11:23 HHCHD902I console_shutdown complete
00:11:23 HHCHD901I Calling term_sockdev
00:11:23 HHCHD902I term_sockdev complete
00:11:23 HHCHD901I Calling hdl_term
00:11:23 HHCHD950I Begin HDL termination sequence
00:11:23 HHCHD951I Calling module *Hercules cleanup routine
00:11:23 HHCHD952I Module *Hercules cleanup complete
00:11:23 HHCHD959I HDL Termination sequence complete
00:11:23 HHCHD902I hdl_term complete
00:11:23 HHCHD901I Calling logger_term
00:11:23 HHCLG014I logger thread terminating

[[e-mail] [hercules-390]]

Hyperion:

00:11:30 HHC01413I Hercules version 4.0.0.0 (4.0.0.0)
00:11:30 HHC01414I (C) Copyright 1999-2016 by Roger Bowler, Jan Jaeger, and others
00:11:30 HHC01415I Build date: Dec 16 2016 at 14:14:30
00:11:30 HHC01417I Built with: Microsoft Visual C 190024215 1
00:11:30 HHC01417I Build type: Windows MSVC i386 host architecture build
00:11:30 HHC01417I Modes: S/370 ESA/390 z/Arch
00:11:30 HHC01417I Max CPU Engines: 32
00:11:30 HHC01417I Using Fish threads Threading Model
00:11:30 HHC01417I Using Error-Checking Mutex Locking Model
00:11:30 HHC01417I With Syncio support
00:11:30 HHC01417I With Shared Devices support
00:11:30 HHC01417I With Dynamic loading support
00:11:30 HHC01417I Using shared libraries
00:11:30 HHC01417I With External GUI support
00:11:30 HHC01417I With Partial TCP keepalive support
00:11:30 HHC01417I With IPV6 support
00:11:30 HHC01417I With HTTP Server support
00:11:30 HHC01417I With sqrtl support
00:11:30 HHC01417I Without SIGABEND handler
00:11:30 HHC01417I With CCKD BZIP2 support
00:11:30 HHC01417I With HET BZIP2 support
00:11:30 HHC01417I With ZLIB support
00:11:30 HHC01417I With Regular Expressions support
00:11:30 HHC01417I With Object REXX support
00:11:30 HHC01417I With Regina REXX support
00:11:30 HHC01417I With Automatic Operator support
00:11:30 HHC01417I Without National Language Support
00:11:30 HHC01417I Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8 fetch_dw store_dw hatomics=msvcIntrinsics
00:11:30 HHC01417I Running on: PAUL-DELL (Windows-6.2.9200 Intel(R) x64) LP=8, Cores=4, CPUs=1
00:11:30 HHC00018W Hercules is NOT running in elevated mode
00:11:30 HHC02323W This build of Hercules has only partial TCP keepalive support
00:11:30 HHC01508I HDL: loadable module directory is c:/herc380/
00:11:30 HHC00150I Crypto module loaded (c) Copyright 2003-2016 by Bernard van der Helm
00:11:30 HHC00151I Activated facility: Message Security Assist
00:11:30 HHC00151I Activated facility: Message Security Assist Extension 1, 2, 3 and 4
00:11:30 HHC00100I Thread id 00000b44, prio 15, name Processor CP00 started
00:11:30 HHC00100I Thread id 00001ea0, prio -20, name Timer started
00:11:30 HHC00811I Processor CP00: architecture mode z/Arch
00:11:30 HHC02204I cpuserial set to 000611
00:11:30 HHC02204I cpumodel set to 4381
00:11:30 HHC17003I MAIN storage is 200M (mainsize); storage is not locked
00:11:30 HHC17003I EXPANDED storage is 0 (xpndsize); storage is not locked
00:11:30 HHC00811I Processor CP00: architecture mode S/370
00:11:30 HHC02204I archmode set to S/370
00:11:30 HHC02203I default allowed automount directory: c:/mvs380/
00:11:30 HHC02204I mounted_tape_reinit set to disabled
00:11:30 HHC01474I Using internal codepage conversion table 819/1047
00:11:30 HHC02256W Command httpport is deprecated, use http port nnnn [[noauth]|[auth user pass]] instead
00:11:30 HHC02204I httpport set to port=8081 noauth
00:11:30 HHC01807I HTTP server signaled to start
00:11:30 HHC02204I todprio set to -20
00:11:30 HHC00100I Thread id 00002ee4, prio 0, name HTTP server started
00:11:30 HHC02204I hercprio set to 8
00:11:30 HHC02204I devprio set to 0
00:11:30 HHC02204I cpuprio set to 0
00:11:30 HHC02204I loadparm set to ........
00:11:30 HHC02204I maxcpu set to 1
00:11:30 HHC02204I numcpu set to 1
00:11:30 HHC01802I HTTP server using root directory c:/herc380/html/
00:11:30 HHC02204I panrate set to FAST
00:11:30 HHC02204I pantitle set to MVS/380 v1.2 running under Hercules-3.07:380-4.0
00:11:30 HHC01803I HTTP server waiting for requests on port 8081
00:11:30 HHC01042I 0:000C COMM: device bound to socket 127.0.0.1:3505
00:11:30 HHC00100I Thread id 00000e80, prio 0, name Socket device listener started
00:11:30 HHC01437I Config file[123] conf/mvs380.conf: including file conf/mvs380_DASD.conf
00:11:30 HHC00403I 0:0148 CKD file dasd/mvsres.148: opening as r/o
00:11:30 HHC00414I 0:0148 CKD file dasd/mvsres.148: cyls 560 heads 30 tracks 16800 trklen 19456
00:11:30 HHC00403I 0:0131 CKD file dasd/sort01.131: opening as r/o
00:11:30 HHC00414I 0:0131 CKD file dasd/sort01.131: cyls 200 heads 20 tracks 4000 trklen 7680
00:11:30 HHC00403I 0:0132 CKD file dasd/sort02.132: opening as r/o
00:11:30 HHC00414I 0:0132 CKD file dasd/sort02.132: cyls 200 heads 20 tracks 4000 trklen 7680
00:11:30 HHC00403I 0:0133 CKD file dasd/sort03.133: opening as r/o
00:11:30 HHC00414I 0:0133 CKD file dasd/sort03.133: cyls 200 heads 20 tracks 4000 trklen 7680
00:11:30 HHC00403I 0:0134 CKD file dasd/sort04.134: opening as r/o
00:11:30 HHC00414I 0:0134 CKD file dasd/sort04.134: cyls 200 heads 20 tracks 4000 trklen 7680
00:11:30 HHC00403I 0:0135 CKD file dasd/sort05.135: opening as r/o
00:11:30 HHC00414I 0:0135 CKD file dasd/sort05.135: cyls 200 heads 20 tracks 4000 trklen 7680
00:11:30 HHC00403I 0:0136 CKD file dasd/sort06.136: opening as r/o
00:11:30 HHC00414I 0:0136 CKD file dasd/sort06.136: cyls 200 heads 20 tracks 4000 trklen 7680
00:11:30 HHC00403I 0:0140 CKD file dasd/work00.140: opening as r/o
00:11:30 HHC00414I 0:0140 CKD file dasd/work00.140: cyls 560 heads 30 tracks 16800 trklen 19456
00:11:30 HHC00414I 0:0152 CKD file dasd/hasp00.152: cyls 404 heads 19 tracks 7676 trklen 13312
00:11:30 HHC00414I 0:0160 CKD file dasd/page00.160: cyls 698 heads 12 tracks 8376 trklen 8704
00:11:30 HHC00414I 0:0161 CKD file dasd/page01.161: cyls 698 heads 12 tracks 8376 trklen 8704
00:11:30 HHC00414I 0:0162 CKD file dasd/page02.162: cyls 698 heads 12 tracks 8376 trklen 8704
00:11:30 HHC00414I 0:0170 CKD file dasd/work01.170: cyls 962 heads 12 tracks 11544 trklen 35840
00:11:30 HHC00403I 0:01A0 CKD file dasd/work02.180: opening as r/o
00:11:30 HHC00414I 0:01A0 CKD file dasd/work02.180: cyls 886 heads 15 tracks 13290 trklen 47616
00:11:30 HHC00403I 0:01B0 CKD file dasd/work03.190: opening as r/o
00:11:30 HHC00414I 0:01B0 CKD file dasd/work03.190: cyls 1114 heads 15 tracks 16710 trklen 56832
00:11:30 HHC00403I 0:01B1 CKD file dasd/mvscat.191: opening as r/o
00:11:30 HHC00414I 0:01B1 CKD file dasd/mvscat.191: cyls 1114 heads 15 tracks 16710 trklen 56832
00:11:30 HHC00403I 0:01B2 CKD file dasd/seasik.192: opening as r/o
00:11:30 HHC00414I 0:01B2 CKD file dasd/seasik.192: cyls 1114 heads 15 tracks 16710 trklen 56832
00:11:30 HHC00414I 0:01B3 CKD file dasd/mvssrc.193: cyls 2226 heads 15 tracks 33390 trklen 56832
00:11:30 HHC00401E 0:01B4 CKD file dasd/pub004.1b4: open error: not found
00:11:30 HHC01463E 0:01B4 device initialization failed
00:11:30 HHC00403I 0:0240 CKD file dasd/pub000.240: opening as r/o
00:11:30 HHC00414I 0:0240 CKD file dasd/pub000.240: cyls 560 heads 30 tracks 16800 trklen 19456
00:11:30 HHC00403I 0:0248 CKD file dasd/mvsdlb.248: opening as r/o
00:11:30 HHC00414I 0:0248 CKD file dasd/mvsdlb.248: cyls 560 heads 30 tracks 16800 trklen 19456
00:11:30 HHC00403I 0:02A0 CKD file dasd/pub002.280: opening as r/o
00:11:30 HHC00414I 0:02A0 CKD file dasd/pub002.280: cyls 1772 heads 15 tracks 26580 trklen 47616
00:11:30 HHC00403I 0:02B1 CKD file dasd/tmptmp.2b1: opening as r/o
00:11:30 HHC00414I 0:02B1 CKD file dasd/tmptmp.2b1: cyls 1114 heads 15 tracks 16710 trklen 56832
00:11:30 HHC00403I 0:02B2 CKD file dasd/xmit90.2b2: opening as r/o
00:11:30 HHC00414I 0:02B2 CKD file dasd/xmit90.2b2: cyls 1114 heads 15 tracks 16710 trklen 56832
00:11:30 HHC00403I 0:0150 CKD file dasd/start1.150: opening as r/o
00:11:30 HHC00414I 0:0150 CKD file dasd/start1.150: cyls 808 heads 19 tracks 15352 trklen 13312
00:11:30 HHC00403I 0:0151 CKD file dasd/spool0.151: opening as r/o
00:11:30 HHC00414I 0:0151 CKD file dasd/spool0.151: cyls 808 heads 19 tracks 15352 trklen 13312
00:11:30 HHC00403I 0:0340 CKD file dasd/cbt000.340: opening as r/o
00:11:30 HHC00414I 0:0340 CKD file dasd/cbt000.340: cyls 555 heads 30 tracks 16650 trklen 19456
00:11:30 HHC00403I 0:0341 CKD file dasd/cbt001.341: opening as r/o
00:11:30 HHC00414I 0:0341 CKD file dasd/cbt001.341: cyls 555 heads 30 tracks 16650 trklen 19456
00:11:30 HHC00403I 0:0342 CKD file dasd/cbt002.342: opening as r/o
00:11:30 HHC00414I 0:0342 CKD file dasd/cbt002.342: cyls 555 heads 30 tracks 16650 trklen 19456
00:11:30 HHC00403I 0:0343 CKD file dasd/cbtcat.343: opening as r/o
00:11:30 HHC00414I 0:0343 CKD file dasd/cbtcat.343: cyls 555 heads 30 tracks 16650 trklen 19456
00:11:30 HHC00403I 0:0348 CKD file dasd/src000.348: opening as r/o
00:11:30 HHC00414I 0:0348 CKD file dasd/src000.348: cyls 555 heads 30 tracks 16650 trklen 19456
00:11:30 HHC00403I 0:0349 CKD file dasd/src001.349: opening as r/o
00:11:30 HHC00414I 0:0349 CKD file dasd/src001.349: cyls 555 heads 30 tracks 16650 trklen 19456
00:11:30 HHC00403I 0:034A CKD file dasd/src002.34a: opening as r/o
00:11:30 HHC00414I 0:034A CKD file dasd/src002.34a: cyls 555 heads 30 tracks 16650 trklen 19456
00:11:30 HHC00403I 0:034B CKD file dasd/srccat.34b: opening as r/o
00:11:30 HHC00414I 0:034B CKD file dasd/srccat.34b: cyls 555 heads 30 tracks 16650 trklen 19456
00:11:30 HHC00403I 0:0149 CKD file dasd/smp001.149: opening as r/o
00:11:30 HHC00414I 0:0149 CKD file dasd/smp001.149: cyls 560 heads 30 tracks 16800 trklen 19456
00:11:30 HHC00403I 0:014A CKD file dasd/smp002.14a: opening as r/o
00:11:30 HHC00414I 0:014A CKD file dasd/smp002.14a: cyls 560 heads 30 tracks 16800 trklen 19456
00:11:30 HHC00403I 0:014B CKD file dasd/smp003.14b: opening as r/o
00:11:30 HHC00414I 0:014B CKD file dasd/smp003.14b: cyls 560 heads 30 tracks 16800 trklen 19456
00:11:30 HHC00403I 0:014C CKD file dasd/smp004.14c: opening as r/o
00:11:30 HHC00414I 0:014C CKD file dasd/smp004.14c: cyls 560 heads 30 tracks 16800 trklen 19456
00:11:30 HHC00403I 0:0700 CKD file dasd/js2sp0.700: opening as r/o
00:11:30 HHC00414I 0:0700 CKD file dasd/js2sp0.700: cyls 555 heads 30 tracks 16650 trklen 19456
00:11:30 HHC00403I 0:0138 CKD file dasd/dlicat.138: opening as r/o
00:11:30 HHC00414I 0:0138 CKD file dasd/dlicat.138: cyls 200 heads 20 tracks 4000 trklen 7680
00:11:30 HHC00403I 0:0139 CKD file dasd/dlisys.139: opening as r/o
00:11:30 HHC00414I 0:0139 CKD file dasd/dlisys.139: cyls 200 heads 20 tracks 4000 trklen 7680
00:11:30 HHC00403I 0:013A CKD file dasd/dli000.13a: opening as r/o
00:11:30 HHC00414I 0:013A CKD file dasd/dli000.13a: cyls 200 heads 20 tracks 4000 trklen 7680
00:11:30 HHC00403I 0:013B CKD file dasd/dli001.13b: opening as r/o
00:11:30 HHC00414I 0:013B CKD file dasd/dli001.13b: cyls 200 heads 20 tracks 4000 trklen 7680
00:11:30 HHC00403I 0:013C CKD file dasd/dli002.13c: opening as r/o
00:11:30 HHC00414I 0:013C CKD file dasd/dli002.13c: cyls 200 heads 20 tracks 4000 trklen 7680
00:11:30 HHC00403I 0:0710 CKD file dasd/js3sp0.710: opening as r/o
00:11:30 HHC00414I 0:0710 CKD file dasd/js3sp0.710: cyls 555 heads 30 tracks 16650 trklen 19456
00:11:30 HHC00403I 0:0711 CKD file dasd/js3res.711: opening as r/o
00:11:30 HHC00414I 0:0711 CKD file dasd/js3res.711: cyls 555 heads 30 tracks 16650 trklen 19456
00:11:30 HHC00100I Thread id 00002b90, prio 0, name Console connection started
00:11:30 HHC01024I Waiting for console connections on port 3270
00:11:30 HHC00222I 0:0400 Tape file *, type aws: option level accepted
00:11:30 HHC00222I 0:0401 Tape file *, type aws: option level accepted
00:11:30 HHC00222I 0:0402 Tape file *, type aws: option level accepted
00:11:30 HHC00222I 0:0403 Tape file *, type aws: option level accepted
00:11:30 HHC00100I Thread id 000004b0, prio 0, name Control panel started
00:11:30 HHC02260I Script 1: begin processing file conf/auto_run.rc
00:11:30 HHC01603I devlist
00:11:30 HHC02279I 0:000C 3505 127.0.0.1:3505 sockdev ascii trunc eof IO[0]
00:11:30 HHC02279I (no one currently connected)
00:11:30 HHC02279I 0:000D 3525 pch/pch00d.txt ascii crlf IO[0]
00:11:30 HHC02279I 0:000E 1403 prt/prt00e.txt crlf noclear print fcbck IO[0]
00:11:30 HHC02279I 0:000F 1403 prt/prt00f.txt crlf noclear print fcbck IO[0]
00:11:30 HHC02279I 0:001F 3215 *syscons cmdpref(/) noprompt IO[0] open
00:11:30 HHC02279I 0:00C0 3270 * IO[0]
00:11:30 HHC02279I 0:00C1 3270 * IO[0]
00:11:30 HHC02279I 0:00C2 3270 * IO[0]
00:11:30 HHC02279I 0:00C7 3287 * IO[0]
00:11:30 HHC02279I 0:010C 3505 jcl/dummy eof IO[0]
00:11:30 HHC02279I 0:0131 2314 dasd/sort01.131 [200 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0132 2314 dasd/sort02.132 [200 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0133 2314 dasd/sort03.133 [200 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0134 2314 dasd/sort04.134 [200 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0135 2314 dasd/sort05.135 [200 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0136 2314 dasd/sort06.136 [200 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0138 2314 dasd/dlicat.138 [200 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0139 2314 dasd/dlisys.139 [200 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:013A 2314 dasd/dli000.13a [200 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:013B 2314 dasd/dli001.13b [200 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:013C 2314 dasd/dli002.13c [200 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0140 3350 dasd/work00.140 [560 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0148 3350 dasd/mvsres.148 [560 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0149 3350 dasd/smp001.149 [560 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:014A 3350 dasd/smp002.14a [560 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:014B 3350 dasd/smp003.14b [560 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:014C 3350 dasd/smp004.14c [560 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0150 3330 dasd/start1.150 [808 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0151 3330 dasd/spool0.151 [808 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0152 3330 dasd/hasp00.152 [404 cyls] [0 sfs] IO[0] open
00:11:30 HHC02279I 0:0160 3340 dasd/page00.160 [698 cyls] [0 sfs] IO[0] open
00:11:30 HHC02279I 0:0161 3340 dasd/page01.161 [698 cyls] [0 sfs] IO[0] open
00:11:30 HHC02279I 0:0162 3340 dasd/page02.162 [698 cyls] [0 sfs] IO[0] open
00:11:30 HHC02279I 0:0170 3375 dasd/work01.170 [962 cyls] [0 sfs] IO[0] open
00:11:30 HHC02279I 0:01A0 3380 dasd/work02.180 [886 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:01B0 3390 dasd/work03.190 [1114 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:01B1 3390 dasd/mvscat.191 [1114 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:01B2 3390 dasd/seasik.192 [1114 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:01B3 3390 dasd/mvssrc.193 [2226 cyls] [0 sfs] IO[0] open
00:11:30 HHC02279I 0:01C7 3287 * IO[0]
00:11:30 HHC02279I 0:0240 3350 dasd/pub000.240 [560 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0248 3350 dasd/mvsdlb.248 [560 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:02A0 3380 dasd/pub002.280 [1772 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:02B1 3390 dasd/tmptmp.2b1 [1114 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:02B2 3390 dasd/xmit90.2b2 [1114 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:030E 1403 log/hardcopy.log crlf noclear print fcbck IO[0]
00:11:30 HHC02279I 0:0340 3350 dasd/cbt000.340 [555 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0341 3350 dasd/cbt001.341 [555 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0342 3350 dasd/cbt002.342 [555 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0343 3350 dasd/cbtcat.343 [555 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0348 3350 dasd/src000.348 [555 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0349 3350 dasd/src001.349 [555 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:034A 3350 dasd/src002.34a [555 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:034B 3350 dasd/srccat.34b [555 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0400 3420 * IO[0] maxsize=0 eotmargin=128K deonirq=N
00:11:30 HHC02279I 0:0401 3420 * IO[0] maxsize=0 eotmargin=128K deonirq=N
00:11:30 HHC02279I 0:0402 3420 * IO[0] maxsize=0 eotmargin=128K deonirq=N
00:11:30 HHC02279I 0:0403 3420 * IO[0] maxsize=0 eotmargin=128K deonirq=N
00:11:30 HHC02279I 0:0700 3350 dasd/js2sp0.700 [555 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0710 3350 dasd/js3sp0.710 [555 cyls] [1 sfs] IO[0] open
00:11:30 HHC02279I 0:0711 3350 dasd/js3res.711 [555 cyls] [1 sfs] IO[0] open
00:11:30 HHC01603I logopt timestamp
00:11:30 HHC02204I logopt set to TIMESTAMP
00:11:30 HHC01603I panrate 1000
00:11:30 HHC02204I panrate set to 1000
00:11:30 HHC01603I hao tgt IEF238D
00:11:30 HHC00077I The target was placed at index 0
00:11:30 HHC01603I hao cmd script conf/cancel.rc
00:11:30 HHC00100I Thread id 00001ec0, prio 0, name Hercules Automatic Operator started
00:11:30 HHC00077I The command was placed at index 0
00:11:30 HHC01603I hao tgt HASP395 DYNAMASK
00:11:30 HHC00077I The target was placed at index 1
00:11:30 HHC01603I hao cmd script conf/subjobs_slow.rc
00:11:30 HHC00077I The command was placed at index 1
00:11:30 HHC01603I hao tgt HASP373 SVC120I
00:11:30 HHC00077I The target was placed at index 2
00:11:30 HHC01603I hao cmd script conf/subjobs_fast.rc
00:11:30 HHC00077I The command was placed at index 2
00:11:30 HHC01603I hao tgt HASP436 REPLY
00:11:30 HHC00077I The target was placed at index 3
00:11:30 HHC01603I hao cmd script conf/replyy.rc
00:11:30 HHC00077I The command was placed at index 3
00:11:30 HHC01603I devinit 402 tapes/mftopc.het
00:11:30 HHC00221I 0:0402 Tape file tapes/mftopc.het, type het: format type Hercules Emulated Tape file
00:11:30 HHC02245I 0:0402 device initialized
00:11:30 HHC01603I devinit 403 tapes/awstap.aws
00:11:30 HHC00221I 0:0403 Tape file tapes/awstap.aws, type het: format type Hercules Emulated Tape file
00:11:30 HHC02245I 0:0403 device initialized
00:11:30 /r 00,clpa,cmd=co
00:11:30 HHC01603I ipl 148
00:11:30 HHC02264I Script 1: file conf/auto_run.rc processing ended
00:11:30 HHC00107I Starting thread cckd_ra(), active=0, started=0, max=2
00:11:30 HHC00100I Thread id 00002a3c, prio 0, name Read-ahead thread-1 started
00:11:30 HHC00107I Starting thread cckd_ra() from cckd_ra(), active=1, started=1, max=2
00:11:30 HHC00100I Thread id 00000fac, prio 0, name Read-ahead thread-2 started
00:11:31 /IEA101A SPECIFY SYSTEM PARMS FOR MVS/380 1.2 v03.8 TK3+
00:11:31 HHC00107I Starting thread cckd_writer(), active=0, started=0, max=2
00:11:31 HHC00100I Thread id 00002b6c, prio 0, name Writer thread-1 started
00:11:31 HHC00107I Starting thread cckd_gcol(), active=0, started=0, max=1
00:11:31 HHC00100I Thread id 00001e18, prio 0, name Garbage collector started
00:11:31 /IEA940I THE FOLLOWING PAGE DATA SETS ARE IN USE
00:11:31 / PLPA ... SYS1.PAGELPA
00:11:31 / COMMON . SYS1.PAGECSA
00:11:31 / DUPLEX . SYS1.DUPLEX
00:11:31 / LOCAL .. SYS1.PAGEL01
00:11:31 / LOCAL .. SYS1.PAGEL02
00:11:31 / LOCAL .. SYS1.PAGEL03
00:11:31 HHC00107I Starting thread cckd_writer() from cckd_writer(), active=1, started=1, max=2
00:11:31 HHC00100I Thread id 00001874, prio 0, name Writer thread-2 started
00:11:33 / IGF992I MIH INIT COMPLETE, PRI=000300, SEC=000015
00:11:33 /*IEE362A SMF ENTER DUMP FOR SYS1.MANX ON MVSRES
00:11:33 / IEE360I SMF NOW RECORDING ON SYS1.MANY ON MVSRES TIME=13.11.33
00:11:33 / IEF677I WARNING MESSAGE(S) FOR JOB JES2 ISSUED
00:11:33 /*00 $HASP436 REPLY Y OR N TO CONFIRM CHECKPOINT RECORD CHANGE
00:11:33 HHC00081I Match at index 03, executing command script conf/replyy.rc
00:11:33 HHC01603I script conf/replyy.rc
00:11:33 HHC02260I Script 2: begin processing file conf/replyy.rc
00:11:33 /reply 00,y
00:11:33 HHC02264I Script 2: file conf/replyy.rc processing ended
00:11:33 / IEE600I REPLY TO 00 IS;SUPPRESSED
00:11:33 / $HASP493 JES2 COLD-START IS IN PROGRESS
00:11:33 / $HASP412 MAXIMUM OF 1 READER(S) EXCEEDED
00:11:33 /13.11.33 IEE041I THE SYSTEM LOG IS NOW ACTIVE
00:11:33 /13.11.33 IEE302I 00F ONLINE
00:11:33 /13.11.33 IEE302I 00E ONLINE
00:11:33 /13.11.33 IEE313I 30E UNIT REF INVALID
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 IEE450I 13.11.34 UNIT STATUS 160
00:11:34 / UNIT TYPE STATUS VOLSER VOLSTATE UNIT TYPE STATUS VOLSER VOLSTATE
00:11:34 / 400 3400 O /REMOV 401 3400 O /REMOV
00:11:34 / 402 3400 O /REMOV
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 $HASP160 PRINTER1 INACTIVE - CLASS=AP
00:11:34 /13.11.34 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:34 /13.11.34 $HASP160 PUNCH1 INACTIVE - CLASS=B
00:11:34 /13.11.34 STC 2 $HASP100 INIT ON STCINRDR
00:11:34 /13.11.34 STC 3 $HASP100 INIT ON STCINRDR
00:11:34 /13.11.34 STC 4 $HASP100 INIT ON STCINRDR
00:11:34 /13.11.34 STC 2 $HASP373 INIT STARTED
00:11:34 /13.11.34 STC 2 IEF403I INIT - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 3 $HASP373 INIT STARTED
00:11:34 /13.11.34 STC 3 IEF403I INIT - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 5 $HASP100 INIT ON STCINRDR
00:11:34 /13.11.34 STC 4 $HASP373 INIT STARTED
00:11:34 /13.11.34 STC 4 IEF403I INIT - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 6 $HASP100 INIT ON STCINRDR
00:11:34 /13.11.34 STC 5 $HASP373 INIT STARTED
00:11:34 /13.11.34 STC 5 IEF403I INIT - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 6 $HASP373 INIT STARTED
00:11:34 /13.11.34 STC 6 IEF403I INIT - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 7 $HASP100 INIT ON STCINRDR
00:11:34 /13.11.34 STC 8 $HASP100 INIT ON STCINRDR
00:11:34 /13.11.34 STC 7 $HASP373 INIT STARTED
00:11:34 /13.11.34 STC 7 IEF403I INIT - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 9 $HASP100 SVC120I ON STCINRDR
00:11:34 /13.11.34 STC 8 $HASP373 INIT STARTED
00:11:34 /13.11.34 STC 8 IEF403I INIT - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 10 $HASP100 DYNABLDL ON STCINRDR
00:11:34 /13.11.34 STC 9 $HASP373 SVC120I STARTED
00:11:34 HHC00081I Match at index 02, executing command script conf/subjobs_fast.rc
00:11:34 HHC01603I script conf/subjobs_fast.rc
00:11:34 HHC02260I Script 3: begin processing file conf/subjobs_fast.rc
00:11:34 HHC01603I hao clear
00:11:34 HHC00080I All HAO rules are cleared
00:11:34 HHC01603I hao tgt HASP250 SVC120I
00:11:34 HHC00077I The target was placed at index 0
00:11:34 HHC01603I hao cmd script conf/subjobs.rc
00:11:34 HHC00077I The command was placed at index 0
00:11:34 HHC02264I Script 3: file conf/subjobs_fast.rc processing ended
00:11:34 /13.11.34 STC 9 IEF403I SVC120I - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 11 $HASP100 DYNAMASK ON STCINRDR
00:11:34 /13.11.34 STC 10 $HASP373 DYNABLDL STARTED
00:11:34 /13.11.34 STC 10 IEF403I DYNABLDL - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 12 $HASP100 BSPPILOT ON STCINRDR
00:11:34 /13.11.34 STC 11 $HASP373 DYNAMASK STARTED
00:11:34 /13.11.34 STC 11 IEF403I DYNAMASK - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 12 $HASP373 BSPPILOT STARTED
00:11:34 /13.11.34 STC 12 IEF403I BSPPILOT - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 13 $HASP100 BSPSETPF ON STCINRDR
00:11:34 /13.11.34 STC 14 $HASP100 LOGRECI ON STCINRDR
00:11:34 /13.11.34 STC 13 $HASP373 BSPSETPF STARTED
00:11:34 /13.11.34 STC 13 IEF403I BSPSETPF - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 15 $HASP100 NET ON STCINRDR
00:11:34 /13.11.34 STC 14 $HASP373 LOGRECI STARTED
00:11:34 /13.11.34 STC 14 IEF403I LOGRECI - STARTED - TIME=13.11.34
00:11:34 /13.11.34 $HASP309 INIT 1 INACTIVE ******** C=A
00:11:34 /13.11.34 $HASP309 INIT 2 INACTIVE ******** C=BA
00:11:34 /13.11.34 $HASP309 INIT 3 INACTIVE ******** C=CBA
00:11:34 /13.11.34 STC 15 $HASP373 NET STARTED
00:11:34 /13.11.34 $HASP309 INIT 4 INACTIVE ******** C=SHB
00:11:34 /13.11.34 STC 15 IEF403I NET - STARTED - TIME=13.11.34
00:11:34 /13.11.34 $HASP309 INIT 5 INACTIVE ******** C=SBA
00:11:34 /13.11.34 $HASP309 INIT 6 INACTIVE ******** C=S
00:11:34 /13.11.34 $HASP309 INIT 7 INACTIVE ******** C=E
00:11:34 /13.11.34 STC 9 BSPGM39E - Hercules and MVS 380 mods required
00:11:34 /13.11.34 STC 9 IEF404I SVC120I - ENDED - TIME=13.11.34
00:11:34 /13.11.34 STC 9 $HASP395 SVC120I ENDED
00:11:34 /13.11.34 STC 9 $HASP150 SVC120I ON PRINTER2 41 LINES
00:11:34 /13.11.34 STC 9 *$HASP190 SVC120I SETUP -- PRINTER2 -- F = 0001 -- C = 6 -- T = SN
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:34 /13.11.34 STC 9 $HASP250 SVC120I IS PURGED
00:11:34 HHC00081I Match at index 00, executing command script conf/subjobs.rc
00:11:34 HHC01603I script conf/subjobs.rc
00:11:34 HHC02260I Script 4: begin processing file conf/subjobs.rc
00:11:34 HHC01603I hao clear
00:11:34 HHC00080I All HAO rules are cleared
00:11:34 HHC01603I hao tgt HASP250 MOUNT
00:11:34 HHC00077I The target was placed at index 0
00:11:34 HHC01603I hao cmd script conf/subjobs2.rc
00:11:34 HHC00077I The command was placed at index 0
00:11:34 /M 401,VOL=(NL,PCTOMF)
00:11:34 HHC02264I Script 4: file conf/subjobs.rc processing ended
00:11:34 /13.11.34 STC 16 $HASP100 MOUNT ON STCINRDR
00:11:34 /13.11.34 STC 10 DYNABLDL STARTED
00:11:34 /13.11.34 STC 16 $HASP373 MOUNT STARTED
00:11:34 /13.11.34 STC 16 IEF403I MOUNT - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 16 *IEF233A M 401,PCTOMF,,MOUNT,401
00:11:34 /13.11.34 STC 10 IEF404I DYNABLDL - ENDED - TIME=13.11.34
00:11:34 /13.11.34 STC 10 $HASP395 DYNABLDL ENDED
00:11:34 /13.11.34 STC 10 $HASP150 DYNABLDL ON PRINTER2 21 LINES
00:11:34 /13.11.34 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:34 /13.11.34 STC 10 $HASP250 DYNABLDL IS PURGED
00:11:34 /13.11.34 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
00:11:34 /13.11.34 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
00:11:34 /13.11.34 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
00:11:34 /13.11.34 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
00:11:34 /13.11.34 STC 15 IST025I BLDL FAILED FOR IEDIAK IN VTAMLIB
00:11:34 /13.11.34 STC 15 IST025I BLDL FAILED FOR IEDIAK IN VTAMLIB
00:11:34 /13.11.34 STC 15 IST110I NETWORK SOLICITOR STARTED
00:11:34 /13.11.34 STC 15 IST093I APPLJRP ACTIVE
00:11:34 /13.11.34 STC 15 IST093I APPLPIES ACTIVE
00:11:34 /13.11.34 STC 15 IST093I APPLPIAD ACTIVE
00:11:34 /13.11.34 STC 11 DMSK00I DYNAMASK DONE ****
00:11:34 /13.11.34 STC 11 DMSK06I START
00:11:34 /13.11.34 STC 15 IST093I APPLTSO ACTIVE
00:11:34 /13.11.34 STC 15 IST093I APPLTEST ACTIVE
00:11:34 /13.11.34 STC 11 IEF404I DYNAMASK - ENDED - TIME=13.11.34
00:11:34 /13.11.34 STC 11 $HASP395 DYNAMASK ENDED
00:11:34 /13.11.34 STC 11 $HASP150 DYNAMASK ON PRINTER2 30 LINES
00:11:34 /13.11.34 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:34 /13.11.34 STC 11 $HASP250 DYNAMASK IS PURGED
00:11:34 /13.11.34 STC 15 IST093I LCLMAJRP ACTIVE
00:11:34 /13.11.34 STC 13 BSPSP91I - Parms passed: NOREPLYU
00:11:34 /13.11.34 STC 13 BSPSP93I - PFK definitions will be updated in memory
00:11:34 /13.11.34 STC 15 IST093I LCLMAJ00 ACTIVE
00:11:34 /13.11.34 STC 17 $HASP100 TSO ON STCINRDR
00:11:34 /13.11.34 STC 18 $HASP100 JRP ON STCINRDR
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 STC 17 $HASP373 TSO STARTED
00:11:34 /13.11.34 STC 17 IEF403I TSO - STARTED - TIME=13.11.34
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 STC 15 IST020I VTAM INITIALIZATION COMPLETE
00:11:34 /13.11.34 STC 18 $HASP373 JRP STARTED
00:11:34 /13.11.34 STC 18 IEF403I JRP - STARTED - TIME=13.11.34
00:11:34 /13.11.34 STC 15 IEA000I 0C1,IOE,05,0200,400000000001,,,NET ,13.11.34
00:11:34 /13.11.34 STC 15 IEA000I 0C0,IOE,05,0200,400000000001,,,NET ,13.11.34
00:11:34 /13.11.34 STC 15 IEA000I 0C2,IOE,05,0200,400000000001,,,NET ,13.11.34
00:11:34 /13.11.34 STC 13 BSPSP22I - Dataset processed: SYS1.PARMLIB
00:11:34 /13.11.34 STC 13 BSPSP23I - on volume MVSRES
00:11:34 /13.11.34 STC 13 BSPSP21I - Member being processed: SETPFK01
00:11:34 /13.11.34 STC 14 IFC001I D=3350 N=0B F=01AB0000 L=01AC0005 S=01AB000002 DIP COMPLETE
00:11:34 /13.11.34 STC 14 IEF404I LOGRECI - ENDED - TIME=13.11.34
00:11:34 /13.11.34 STC 14 $HASP395 LOGRECI ENDED
00:11:34 /13.11.34 STC 14 $HASP150 LOGRECI ON PRINTER2 20 LINES
00:11:34 /13.11.34 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:34 /13.11.34 STC 14 $HASP250 LOGRECI IS PURGED
00:11:34 /13.11.34 STC 16 IEF404I MOUNT - ENDED - TIME=13.11.34
00:11:34 /13.11.34 STC 16 $HASP395 MOUNT ENDED
00:11:34 /13.11.34 STC 16 $HASP150 MOUNT ON PRINTER2 18 LINES
00:11:34 /13.11.34 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:34 /13.11.34 STC 16 $HASP250 MOUNT IS PURGED
00:11:34 HHC00081I Match at index 00, executing command script conf/subjobs2.rc
00:11:34 HHC01603I script conf/subjobs2.rc
00:11:34 HHC02260I Script 5: begin processing file conf/subjobs2.rc
00:11:34 HHC01603I hao clear
00:11:34 HHC00080I All HAO rules are cleared
00:11:34 HHC01603I hao tgt IEF238D
00:11:34 HHC00077I The target was placed at index 0
00:11:34 HHC01603I hao cmd script conf/cancel.rc
00:11:34 HHC00077I The command was placed at index 0
00:11:34 HHC01603I hao tgt IEC301A
00:11:34 HHC00077I The target was placed at index 1
00:11:34 HHC01603I hao cmd script conf/secret.rc
00:11:34 HHC00077I The command was placed at index 1
00:11:34 HHC01603I devinit 401 tapes/pctomf.tdf
00:11:34 HHC00221I 0:0401 Tape file tapes/pctomf.tdf, type oma: format type Optical Media Attachment (OMA) tape
00:11:34 HHC02245I 0:0401 device initialized
00:11:34 HHC01603I hao tgt HASP373 TERMHERC
00:11:34 HHC00077I The target was placed at index 2
00:11:34 HHC01603I hao cmd script conf/termherc.rc
00:11:34 HHC00077I The command was placed at index 2
00:11:34 HHC01603I devinit 00c jcl/hercauto.jcl eof
00:11:34 HHC01046I 0:000C COMM: device unbound from socket 127.0.0.1:3505
00:11:34 HHC00101I Thread id 00000e80, prio 0, name Socket device listener ended
00:11:34 HHC02245I 0:000C device initialized
00:11:34 HHC02264I Script 5: file conf/subjobs2.rc processing ended
00:11:34 /13.11.34 JOB 1 $HASP100 HEXDUMP ON READER1
00:11:34 /13.11.34 JOB 2 $HASP100 TERMHERC ON READER1
00:11:34 /13.11.34 STC 13 +BSPSP98I - Member processed, LASTCC=0000
00:11:34 /13.11.34 STC 13 +BSPSP21I - Member being processed: SETPFK02
00:11:34 /13.11.34 JOB 1 $HASP373 HEXDUMP STARTED - INIT 3 - CLASS C - SYS BSP1
00:11:34 /13.11.34 JOB 1 IEF403I HEXDUMP - STARTED - TIME=13.11.34
00:11:34 /13.11.34 JOB 1 *IEF233A M 401,PCTOMF,,HEXDUMP,HEXDUMP
00:11:34 /13.11.34 STC 13 +BSPSP98I - Member processed, LASTCC=0000
00:11:34 /13.11.34 STC 13 +BSPSP99I - End of processing, MAXRC=0000
00:11:34 /13.11.34 STC 13 IEF404I BSPSETPF - ENDED - TIME=13.11.34
00:11:34 /13.11.34 STC 13 $HASP395 BSPSETPF ENDED
00:11:34 /13.11.34 STC 13 $HASP150 BSPSETPF ON PRINTER2 34 LINES
00:11:34 /13.11.34 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:34 /13.11.34 STC 13 $HASP250 BSPSETPF IS PURGED
00:11:34 /13.11.34 STC 17 IKT007I TCAS ACCEPTING LOGONS
00:11:34 /13.11.34 STC 17 IKT005I TCAS IS INITIALIZED
00:11:34 /13.11.34 JOB 1 IEC705I TAPE ON 402,MFTOPC,SL,6250 BPI,HEXDUMP,HEXDUMP
00:11:34 /13.11.34 STC 18 JRPI101 INITIALIZATION COMPLETE
00:11:34 /13.11.34 STC 18 *01 JRP100I - ENTER ICLOSE TO SHUT DOWN
00:11:34 HHC00201I 0:0401 Tape file tapes/pctomf.tdf, type oma: tape closed
00:11:34 HHC00201I 0:0401 Tape file tapes/pctomf.tdf, type oma: tape closed
00:11:34 HHC00201I 0:0402 Tape file tapes/mftopc.het, type het: tape closed
00:11:34 /13.11.34 JOB 1 IEF234E K 402,MFTOPC,PVT,HEXDUMP,HEXDUMP
00:11:34 /13.11.34 JOB 1 IEFACTRT - Stepname Procstep Program Retcode
00:11:34 /13.11.34 JOB 1 HEXDUMP HEXDUMP HEXDUMP RC= 0000
00:11:34 /13.11.34 JOB 1 IEF404I HEXDUMP - ENDED - TIME=13.11.34
00:11:34 /13.11.34 JOB 1 $HASP395 HEXDUMP ENDED
00:11:34 /13.11.34 JOB 1 $HASP150 HEXDUMP ON PRINTER1 55 LINES
00:11:34 /13.11.34 JOB 1 *$HASP190 HEXDUMP SETUP -- PRINTER1 -- F = 0001 -- C = 6 -- T = SN
00:11:34 /13.11.34 $HASP000 OK
00:11:34 /13.11.34 JOB 2 $HASP373 TERMHERC STARTED - INIT 3 - CLASS C - SYS BSP1
00:11:34 HHC00081I Match at index 02, executing command script conf/termherc.rc
00:11:34 HHC01603I script conf/termherc.rc
00:11:34 HHC02260I Script 6: begin processing file conf/termherc.rc
00:11:34 HHC01603I hao clear
00:11:34 HHC00080I All HAO rules are cleared
00:11:34 HHC01603I hao tgt HASP250 TERMHERC
00:11:34 HHC00077I The target was placed at index 0
00:11:34 HHC01603I hao cmd script conf/termherc2.rc
00:11:34 HHC00077I The command was placed at index 0
00:11:34 HHC02264I Script 6: file conf/termherc.rc processing ended
00:11:34 /13.11.34 JOB 2 IEF403I TERMHERC - STARTED - TIME=13.11.34
00:11:34 /13.11.34 $HASP160 PRINTER1 INACTIVE - CLASS=AP
00:11:34 /13.11.34 JOB 1 $HASP250 HEXDUMP IS PURGED
00:11:34 /13.11.34 JOB 2 IEFACTRT - Stepname Procstep Program Retcode
00:11:34 /13.11.34 JOB 2 TERMHERC S1 IEBGENER RC= 0000
00:11:34 /13.11.34 JOB 2 IEF404I TERMHERC - ENDED - TIME=13.11.34
00:11:34 /13.11.34 JOB 2 $HASP395 TERMHERC ENDED
00:11:34 /13.11.34 $HASP309 INIT 3 INACTIVE ******** C=CBA
00:11:34 /13.11.34 JOB 2 $HASP150 TERMHERC ON PRINTER2 44 LINES
00:11:34 /13.11.34 JOB 2 $HASP150 TERMHERC ON PRINTER1 1 LINE
00:11:34 /13.11.34 $HASP160 PRINTER1 INACTIVE - CLASS=AP
00:11:34 /13.11.34 $HASP160 PRINTER2 INACTIVE - CLASS=Z
00:11:34 /13.11.34 JOB 2 $HASP250 TERMHERC IS PURGED
00:11:34 HHC00081I Match at index 00, executing command script conf/termherc2.rc
00:11:34 HHC01603I script conf/termherc2.rc
00:11:34 HHC02260I Script 7: begin processing file conf/termherc2.rc
00:11:34 HHC01603I quit
00:11:34 HHC01420I Begin Hercules shutdown
00:11:34 HHC00101I Thread id 00001ec0, prio 0, name Hercules Automatic Operator ended
00:11:34 HHC00101I Thread id 00001ea0, prio -20, name Timer ended
00:11:34 HHC01423I Calling termination routines
00:11:34 HHC02272I Highest observed MIPS and IO/s rates
00:11:34 HHC02272I from Sat Jan 21 00:00:00 2017
00:11:34 HHC02272I to Sat Jan 21 00:11:34 2017
00:11:34 HHC02272I MIPS: 96.943593 IO/s: 2234
00:11:34 HHC00101I Thread id 00002ee4, prio 0, name HTTP server ended
00:11:34 HHC00101I Thread id 00000b44, prio 0, name Processor CP00 ended
00:11:34 HHC00333I 0:0148 size free nbr st reads writes l2reads hits switches
00:11:34 HHC00334I 0:0148 readaheads misses
00:11:34 HHC00335I 0:0148 --------------------------------------------------------------------
00:11:34 HHC00336I 0:0148 [*] 0019298902 004 % 0037 0001282 0000025 0000035 0001253 0002016
00:11:34 HHC00337I 0:0148 0000529 0000077
00:11:34 HHC00338I 0:0148 dasd/mvsres.148
00:11:34 HHC00339I 0:0148 [0] 0015179178 000 % 0001 ro 0001090 0000000 0000018
00:11:34 HHC00340I 0:0148 shadow/mvsres_*.148
00:11:34 HHC00341I 0:0148 [1] 0004119724 016 % 0036 0000192 0000025 0000017
00:11:34 HHC00333I 0:0131 size free nbr st reads writes l2reads hits switches
00:11:34 HHC00335I 0:0131 --------------------------------------------------------------------
00:11:34 HHC00336I 0:0131 [*] 0000035424 000 % 0001 0000001 0000000 0000001 0000000 0000001
00:11:34 HHC00338I 0:0131 dasd/sort01.131
00:11:34 HHC00339I 0:0131 [0] 0000034336 000 % 0001 ro 0000001 0000000 0000001
00:11:34 HHC00340I 0:0131 shadow/sort01_*.131
00:11:34 HHC00341I 0:0131 [1] 0000001088 000 % 0000 0000000 0000000 0000000
00:11:34 HHC00333I 0:0132 size free nbr st reads writes l2reads hits switches
00:11:34 HHC00335I 0:0132 --------------------------------------------------------------------
00:11:34 HHC00336I 0:0132 [*] 0000035424 000 % 0001 0000001 0000000 0000001 0000000 0000001
00:11:34 HHC00338I 0:0132 dasd/sort02.132
00:11:34 HHC00339I 0:0132 [0] 0000034336 000 % 0001 ro 0000001 0000000 0000001
00:11:34 HHC00340I 0:0132 shadow/sort02_*.132
00:11:34 HHC00341I 0:0132 [1] 0000001088 000 % 0000 0000000 0000000 0000000
00:11:34 HHC00333I 0:0133 size free nbr st reads writes l2reads hits switches
00:11:34 HHC00335I 0:0133 --------------------------------------------------------------------
00:11:34 HHC00336I 0:0133 [*] 0000035424 000 % 0001 0000001 0000000 0000001 0000000 0000001
00:11:34 HHC00338I 0:0133 dasd/sort03.133
00:11:34 HHC00339I 0:0133 [0] 0000034336 000 % 0001 ro 0000001 0000000 0000001
00:11:34 HHC00340I 0:0133 shadow/sort03_*.133
00:11:34 HHC00341I 0:0133 [1] 0000001088 000 % 0000 0000000 0000000 0000000
00:11:34 HHC00333I 0:0134 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0134 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0134 [*] 0000035424 000 % 0001 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:0134 dasd/sort04.134
00:11:35 HHC00339I 0:0134 [0] 0000034336 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0134 shadow/sort04_*.134
00:11:35 HHC00341I 0:0134 [1] 0000001088 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:0135 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0135 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0135 [*] 0000035424 000 % 0001 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:0135 dasd/sort05.135
00:11:35 HHC00339I 0:0135 [0] 0000034336 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0135 shadow/sort05_*.135
00:11:35 HHC00341I 0:0135 [1] 0000001088 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:0136 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0136 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0136 [*] 0000035424 000 % 0001 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:0136 dasd/sort06.136
00:11:35 HHC00339I 0:0136 [0] 0000034336 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0136 shadow/sort06_*.136
00:11:35 HHC00341I 0:0136 [1] 0000001088 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:0140 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0140 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0140 [*] 0052422417 002 % 0045 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:0140 dasd/work00.140
00:11:35 HHC00339I 0:0140 [0] 0000141963 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0140 shadow/work00_*.140
00:11:35 HHC00341I 0:0140 [1] 0052280454 002 % 0044 0000000 0000000 0000001
00:11:35 HHC00333I 0:0152 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0152 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0152 [*] 0005421226 011 % 0004 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:0152 dasd/hasp00.152
00:11:35 HHC00339I 0:0152 [0] 0005421226 011 % 0004 rw 0000001 0000000 0000001
00:11:35 HHC00333I 0:0160 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00334I 0:0160 readaheads misses
00:11:35 HHC00335I 0:0160 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0160 [*] 0014381709 039 % 0259 0001873 0001370 0000008 0001204 0002362
00:11:35 HHC00337I 0:0160 0000715 0000158
00:11:35 HHC00338I 0:0160 dasd/page00.160
00:11:35 HHC00339I 0:0160 [0] 0014381709 039 % 0259 rw 0001873 0001370 0000008
00:11:35 HHC00333I 0:0161 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00334I 0:0161 readaheads misses
00:11:35 HHC00335I 0:0161 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0161 [*] 0003889872 015 % 0025 0000046 0001515 0000032 0000037 0000056
00:11:35 HHC00337I 0:0161 0000027 0000004
00:11:35 HHC00338I 0:0161 dasd/page01.161
00:11:35 HHC00339I 0:0161 [0] 0003889872 015 % 0025 rw 0000046 0001515 0000032
00:11:35 HHC00333I 0:0162 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00334I 0:0162 readaheads misses
00:11:35 HHC00335I 0:0162 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0162 [*] 0003373857 007 % 0038 0000039 0000035 0000001 0000037 0000052
00:11:35 HHC00337I 0:0162 0000024 0000003
00:11:35 HHC00338I 0:0162 dasd/page02.162
00:11:35 HHC00339I 0:0162 [0] 0003373857 007 % 0038 rw 0000039 0000035 0000001
00:11:35 HHC00333I 0:0170 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0170 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0170 [*] 0057202932 001 % 0014 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:0170 dasd/work01.170
00:11:35 HHC00339I 0:0170 [0] 0057202932 001 % 0014 rw 0000001 0000000 0000001
00:11:35 HHC00333I 0:01A0 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:01A0 --------------------------------------------------------------------
00:11:35 HHC00336I 0:01A0 [*] 0066242054 001 % 0300 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:01A0 dasd/work02.180
00:11:35 HHC00339I 0:01A0 [0] 0000113799 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:01A0 shadow/work02_*.180
00:11:35 HHC00341I 0:01A0 [1] 0066128255 001 % 0299 0000000 0000000 0000001
00:11:35 HHC00333I 0:01B0 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:01B0 --------------------------------------------------------------------
00:11:35 HHC00336I 0:01B0 [*] 0056355632 001 % 0158 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:01B0 dasd/work03.190
00:11:35 HHC00339I 0:01B0 [0] 0000142257 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:01B0 shadow/work03_*.190
00:11:35 HHC00341I 0:01B0 [1] 0056213375 002 % 0157 0000000 0000000 0000001
00:11:35 HHC00333I 0:01B1 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:01B1 --------------------------------------------------------------------
00:11:35 HHC00336I 0:01B1 [*] 0017037777 009 % 0016 0000004 0000000 0000003 0000000 0000004
00:11:35 HHC00338I 0:01B1 dasd/mvscat.191
00:11:35 HHC00339I 0:01B1 [0] 0003658727 000 % 0001 ro 0000003 0000000 0000002
00:11:35 HHC00340I 0:01B1 shadow/mvscat_*.191
00:11:35 HHC00341I 0:01B1 [1] 0013379050 011 % 0015 0000001 0000000 0000001
00:11:35 HHC00333I 0:01B2 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:01B2 --------------------------------------------------------------------
00:11:35 HHC00336I 0:01B2 [*] 0103500159 017 % 1297 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:01B2 dasd/seasik.192
00:11:35 HHC00339I 0:01B2 [0] 0016164960 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:01B2 shadow/seasik_*.192
00:11:35 HHC00341I 0:01B2 [1] 0087335199 020 % 1297 0000000 0000000 0000001
00:11:35 HHC00333I 0:01B3 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:01B3 --------------------------------------------------------------------
00:11:35 HHC00336I 0:01B3 [*] 0168333900 004 % 5454 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:01B3 dasd/mvssrc.193
00:11:35 HHC00339I 0:01B3 [0] 0168333900 004 % 5454 rw 0000001 0000000 0000001
00:11:35 HHC00333I 0:0240 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00334I 0:0240 readaheads misses
00:11:35 HHC00335I 0:0240 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0240 [*] 0044516465 002 % 0019 0000044 0000000 0000009 0000039 0000068
00:11:35 HHC00337I 0:0240 0000015 0000003
00:11:35 HHC00338I 0:0240 dasd/pub000.240
00:11:35 HHC00339I 0:0240 [0] 0007591138 003 % 0001 ro 0000013 0000000 0000004
00:11:35 HHC00340I 0:0240 shadow/pub000_*.240
00:11:35 HHC00341I 0:0240 [1] 0036925327 002 % 0018 0000031 0000000 0000005
00:11:35 HHC00333I 0:0248 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0248 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0248 [*] 0025896197 001 % 0007 0000005 0000002 0000005 0000001 0000006
00:11:35 HHC00338I 0:0248 dasd/mvsdlb.248
00:11:35 HHC00339I 0:0248 [0] 0025471539 000 % 0001 ro 0000003 0000000 0000003
00:11:35 HHC00340I 0:0248 shadow/mvsdlb_*.248
00:11:35 HHC00341I 0:0248 [1] 0000424658 064 % 0006 0000002 0000002 0000002
00:11:35 HHC00333I 0:02A0 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:02A0 --------------------------------------------------------------------
00:11:35 HHC00336I 0:02A0 [*] 0100064666 008 % 0539 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:02A0 dasd/pub002.280
00:11:35 HHC00339I 0:02A0 [0] 0002171954 029 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:02A0 shadow/pub002_*.280
00:11:35 HHC00341I 0:02A0 [1] 0097892712 008 % 0538 0000000 0000000 0000001
00:11:35 HHC00333I 0:02B1 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:02B1 --------------------------------------------------------------------
00:11:35 HHC00336I 0:02B1 [*] 0000143545 000 % 0001 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:02B1 dasd/tmptmp.2b1
00:11:35 HHC00339I 0:02B1 [0] 0000142257 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:02B1 shadow/tmptmp_*.2b1
00:11:35 HHC00341I 0:02B1 [1] 0000001288 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:02B2 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:02B2 --------------------------------------------------------------------
00:11:35 HHC00336I 0:02B2 [*] 0000143545 000 % 0001 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:02B2 dasd/xmit90.2b2
00:11:35 HHC00339I 0:02B2 [0] 0000142257 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:02B2 shadow/xmit90_*.2b2
00:11:35 HHC00341I 0:02B2 [1] 0000001288 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:0150 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0150 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0150 [*] 0006099280 000 % 0000 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:0150 dasd/start1.150
00:11:35 HHC00339I 0:0150 [0] 0006098016 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0150 shadow/start1_*.150
00:11:35 HHC00341I 0:0150 [1] 0000001264 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:0151 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0151 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0151 [*] 0004595678 000 % 0000 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:0151 dasd/spool0.151
00:11:35 HHC00339I 0:0151 [0] 0004594414 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0151 shadow/spool0_*.151
00:11:35 HHC00341I 0:0151 [1] 0000001264 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:0340 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0340 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0340 [*] 0050622559 000 % 0000 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:0340 dasd/cbt000.340
00:11:35 HHC00339I 0:0340 [0] 0050621271 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0340 shadow/cbt000_*.340
00:11:35 HHC00341I 0:0340 [1] 0000001288 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:0341 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0341 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0341 [*] 0053836805 000 % 0000 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:0341 dasd/cbt001.341
00:11:35 HHC00339I 0:0341 [0] 0053835517 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0341 shadow/cbt001_*.341
00:11:35 HHC00341I 0:0341 [1] 0000001288 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:0342 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0342 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0342 [*] 0046082980 000 % 0000 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:0342 dasd/cbt002.342
00:11:35 HHC00339I 0:0342 [0] 0046081692 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0342 shadow/cbt002_*.342
00:11:35 HHC00341I 0:0342 [1] 0000001288 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:0343 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0343 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0343 [*] 0027241782 000 % 0000 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:0343 dasd/cbtcat.343
00:11:35 HHC00339I 0:0343 [0] 0027240494 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0343 shadow/cbtcat_*.343
00:11:35 HHC00341I 0:0343 [1] 0000001288 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:0348 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0348 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0348 [*] 0046003602 000 % 0000 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:0348 dasd/src000.348
00:11:35 HHC00339I 0:0348 [0] 0046002314 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0348 shadow/src000_*.348
00:11:35 HHC00341I 0:0348 [1] 0000001288 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:0349 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0349 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0349 [*] 0045707725 000 % 0000 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:0349 dasd/src001.349
00:11:35 HHC00339I 0:0349 [0] 0045706437 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0349 shadow/src001_*.349
00:11:35 HHC00341I 0:0349 [1] 0000001288 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:034A size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:034A --------------------------------------------------------------------
00:11:35 HHC00336I 0:034A [*] 0044403653 000 % 0000 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:034A dasd/src002.34a
00:11:35 HHC00339I 0:034A [0] 0044402365 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:034A shadow/src002_*.34a
00:11:35 HHC00341I 0:034A [1] 0000001288 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:034B size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:034B --------------------------------------------------------------------
00:11:35 HHC00336I 0:034B [*] 0006321674 000 % 0001 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:034B dasd/srccat.34b
00:11:35 HHC00339I 0:034B [0] 0006310767 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:034B shadow/srccat_*.34b
00:11:35 HHC00341I 0:034B [1] 0000010907 007 % 0001 0000000 0000000 0000000
00:11:35 HHC00333I 0:0149 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0149 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0149 [*] 0001118801 011 % 0002 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:0149 dasd/smp001.149
00:11:35 HHC00339I 0:0149 [0] 0000774654 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0149 shadow/smp001_*.149
00:11:35 HHC00341I 0:0149 [1] 0000344147 038 % 0002 0000000 0000000 0000001
00:11:35 HHC00333I 0:014A size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:014A --------------------------------------------------------------------
00:11:35 HHC00336I 0:014A [*] 0001621663 024 % 0012 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:014A dasd/smp002.14a
00:11:35 HHC00339I 0:014A [0] 0000856740 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:014A shadow/smp002_*.14a
00:11:35 HHC00341I 0:014A [1] 0000764923 051 % 0012 0000000 0000000 0000001
00:11:35 HHC00333I 0:014B size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:014B --------------------------------------------------------------------
00:11:35 HHC00336I 0:014B [*] 0001077383 019 % 0003 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:014B dasd/smp003.14b
00:11:35 HHC00339I 0:014B [0] 0000592555 000 % 0000 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:014B shadow/smp003_*.14b
00:11:35 HHC00341I 0:014B [1] 0000484828 042 % 0003 0000000 0000000 0000001
00:11:35 HHC00333I 0:014C size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:014C --------------------------------------------------------------------
00:11:35 HHC00336I 0:014C [*] 0003437923 036 % 0004 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:014C dasd/smp004.14c
00:11:35 HHC00339I 0:014C [0] 0002916431 035 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:014C shadow/smp004_*.14c
00:11:35 HHC00341I 0:014C [1] 0000521492 041 % 0003 0000000 0000000 0000001
00:11:35 HHC00333I 0:0700 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00334I 0:0700 readaheads misses
00:11:35 HHC00335I 0:0700 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0700 [*] 0009850472 001 % 0140 0000109 0000102 0000006 0000772 0000854
00:11:35 HHC00337I 0:0700 0000031 0000015
00:11:35 HHC00338I 0:0700 dasd/js2sp0.700
00:11:35 HHC00339I 0:0700 [0] 0000142291 000 % 0001 ro 0000000 0000000 0000001
00:11:35 HHC00340I 0:0700 shadow/js2sp0_*.700
00:11:35 HHC00341I 0:0700 [1] 0009708181 001 % 0139 0000109 0000102 0000005
00:11:35 HHC00333I 0:0138 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0138 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0138 [*] 0000715081 000 % 0001 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:0138 dasd/dlicat.138
00:11:35 HHC00339I 0:0138 [0] 0000036630 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0138 shadow/dlicat_*.138
00:11:35 HHC00341I 0:0138 [1] 0000678451 000 % 0000 0000000 0000000 0000001
00:11:35 HHC00333I 0:0139 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0139 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0139 [*] 0000880289 000 % 0001 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:0139 dasd/dlisys.139
00:11:35 HHC00339I 0:0139 [0] 0000036630 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0139 shadow/dlisys_*.139
00:11:35 HHC00341I 0:0139 [1] 0000843659 000 % 0000 0000000 0000000 0000001
00:11:35 HHC00333I 0:013A size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:013A --------------------------------------------------------------------
00:11:35 HHC00336I 0:013A [*] 0000043495 000 % 0001 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:013A dasd/dli000.13a
00:11:35 HHC00339I 0:013A [0] 0000036630 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:013A shadow/dli000_*.13a
00:11:35 HHC00341I 0:013A [1] 0000006865 000 % 0000 0000000 0000000 0000001
00:11:35 HHC00333I 0:013B size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:013B --------------------------------------------------------------------
00:11:35 HHC00336I 0:013B [*] 0000046911 000 % 0001 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:013B dasd/dli001.13b
00:11:35 HHC00339I 0:013B [0] 0000036630 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:013B shadow/dli001_*.13b
00:11:35 HHC00341I 0:013B [1] 0000010281 000 % 0000 0000000 0000000 0000001
00:11:35 HHC00333I 0:013C size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:013C --------------------------------------------------------------------
00:11:35 HHC00336I 0:013C [*] 0000037718 000 % 0001 0000001 0000000 0000001 0000000 0000001
00:11:35 HHC00338I 0:013C dasd/dli002.13c
00:11:35 HHC00339I 0:013C [0] 0000036630 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:013C shadow/dli002_*.13c
00:11:35 HHC00341I 0:013C [1] 0000001088 000 % 0000 0000000 0000000 0000000
00:11:35 HHC00333I 0:0710 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0710 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0710 [*] 0001233964 000 % 0001 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:0710 dasd/js3sp0.710
00:11:35 HHC00339I 0:0710 [0] 0000141965 000 % 0001 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0710 shadow/js3sp0_*.710
00:11:35 HHC00341I 0:0710 [1] 0001091999 000 % 0000 0000000 0000000 0000001
00:11:35 HHC00333I 0:0711 size free nbr st reads writes l2reads hits switches
00:11:35 HHC00335I 0:0711 --------------------------------------------------------------------
00:11:35 HHC00336I 0:0711 [*] 0000951745 000 % 0002 0000001 0000000 0000002 0000000 0000001
00:11:35 HHC00338I 0:0711 dasd/js3res.711
00:11:35 HHC00339I 0:0711 [0] 0000142093 000 % 0002 ro 0000001 0000000 0000001
00:11:35 HHC00340I 0:0711 shadow/js3res_*.711
00:11:35 HHC00341I 0:0711 [1] 0000809652 000 % 0000 0000000 0000000 0000001
00:11:35 HHC00101I Thread id 00000fac, prio 0, name Read-ahead thread-2 ended
00:11:35 HHC00101I Thread id 00002a3c, prio 0, name Read-ahead thread-1 ended
00:11:35 HHC00101I Thread id 00001e18, prio 0, name Garbage collector ended
00:11:35 HHC00101I Thread id 00001874, prio 0, name Writer thread-2 ended
00:11:35 HHC00101I Thread id 00002b6c, prio 0, name Writer thread-1 ended
00:11:35 HHC00101I Thread id 00002b90, prio 0, name Console connection ended
00:11:35 HHC00201I 0:0403 Tape file tapes/awstap.aws, type het: tape closed
00:11:35 HHC01427I Main storage released
00:11:35 HHC01427I Expanded storage released
00:11:35 HHC01422I Configuration released
00:11:35 HHC02103I Logger: logger thread terminating
00:11:35 HHC02264I Script 7: file conf/termherc2.rc processing ended
00:11:35 HHC00101I Thread id 000004b0, prio 0, name Control panel ended

[Maarten Hoes [e-mail] [hercules-390]]

Hi,


Just a random thought popping up in my head while I read this thread, but
perhaps someone is in possession of a profiler they can use to more clearly
see if/what the differences are, and where the time is spent in the code ?


- Maarten

[[e-mail] [hercules-390]]

Paul doesn't seem to run a job long enough to differentiate Hercules startup/shutdown differences between the 2 versions or his job which may run the same length of time. We haven't seen a CPU time on the sysout for the 2 instances.

You can run some benchmarks to determine some type of differences between 4.0 and 3.12. Things like dhrystone, whetstone and nbench. All in the files section, all ready to submit.

See the "MIPs Testing" folder at:

https://groups.yahoo.com/neo/groups/hercules-390/files/MIPs%20Testing/ https://groups.yahoo.com/neo/groups/hercules-390/files/MIPs%20Testing/

dhrystone.zip
whetfix.txt
nbench-b1.zip

Phil

[Robert Prins [e-mail] [hercules-390]]

There's only one fool-proof way of finding out why/if Hyperion is slower,
and that is to compare at least some of the inner loops of the code, and
emulation of the most frequently used instructions generated for both 3.xx
and 4.00.

And if some longer running code is required, I've got a nice bit of PL/I
compiled with the "count,flow" options that executes 3,718,941,590 PL/I
statements, so rather a lot more z/OS ones, and a hell of a lot more on the
underlying x86 box...

Post by ***@hotmail.com [hercules-390]
Paul doesn't seem to run a job long enough to differentiate Hercules
startup/shutdown differences between the 2 versions or his job which may
run the same length of time. We haven't seen a CPU time on the sysout for
the 2 instances.
You can run some benchmarks to determine some type of differences between
4.0 and 3.12. Things like dhrystone, whetstone and nbench. All in the
files section, all ready to submit.
https://groups.yahoo.com/neo/groups/hercules-390/files/MIPs%20Testing/
dhrystone.zip
whetfix.txt
nbench-b1.zip
Phil

['\'Fish\' (David B. Trout)' [e-mail] [hercules-390]]

Post by ***@hotmail.com [hercules-390]
Paul doesn't seem to run a job long enough to differentiate
Hercules startup/shutdown differences between the 2 versions

The question I was going to ask was alone the same lines: what two timing points is he using? Is he timing from the "ipl" command to some guest log message that indicates it has completed its initialization? (and is ready for work)

Or is he timing from the first guest message that gets issued when his auto-submitted job first starts to the guest message that gets issued when that same job finishes?

Or is he measuring from the very first Hercules log message to the very last?

Because you are quite right Phil that variations in the length of time it takes for Hercules to initialize (startup) or shutdown across different versions of Hercules is generally speaking largely unimportant (unless we're talking many, many seconds or minutes perhaps).

Benchmarking is both an art and a science and you need to be very careful regarding not only what you're actually measuring but also HOW you're measuring it. It's easy to get sloppy, leading to false conclusions.


[...]

Post by ***@hotmail.com [hercules-390]
You can run some benchmarks to determine some type of
differences between 4.0 and 3.12. Things like dhrystone,
whetstone and nbench. All in the files section, all
ready to submit.
https://groups.yahoo.com/neo/groups/hercules-390/files/MIPs%20Testing/
dhrystone.zip
whetfix.txt
nbench-b1.zip

That's not a half bad idea. In fact it's a rather good one.

BUT... be aware that you'd only be measuring raw instruction emulation speed, not overall emulator performance. Hyperion 4.0's I/O subsystem was significantly enhanced to comply more closely to the architecture for example, whereas 3.12 is still using the older less-architecturally-compliant I/O subsystem design.

The difference in the performance of the two's I/O subsystem wouldn't be reflected in the pure CPU type benchmarks you suggest.

But still, you idea is a good one Phil: try as much as possible to ensure apples are being compared to apples in the comparison of the two versions, which, at least for instruction speed, the aforementioned benchmark programs should certainly accomplish.

[[e-mail] [hercules-390]]

Post by '\'Fish\' (David B. Trout)' ***@gmail.com [hercules-390]
The question I was going to ask was alone
the same lines: what two timing points is he
using? Is he timing from the "ipl" command
to some guest log message that indicates it
has completed its initialization? (and is ready
for work)

The two timing points are from a little
*before* Hercules is started to a little
*after* Hercules has terminated.

Before the IPL I do a very minor copy:

copy %in% %MVS380%\tapes\hercauto.dat

to set up an OMA tape input for the
MVS job to use.

After Hercules is finished I do a very
minor hetget (which does no work
because it doesn't recognize a
parameter), plus a minor copy of
the printer output.

These things are minimal, and
identical to both 3.12 and Hyperion,
so I don't think it is necessary to
eliminate those.

If you want to be pedantic and see
timings at the exact point before and
after hercules, I can change my
scripts to do that, but they should show
Hyperion even slower, because the exact
same 0.1 second will be shaved off
both sets of timings.

Let me know if you want to see those
results.

In case the above description is too
obtuse, here is the actual code (note
especially the command "time" -
which is what I am using to do
timings):

C:\mvs380_work\mvshd6>type doit.bat
time <NUL: >>time.txt
del out.txt
call mvshd in.txt out.txt
time <NUL: >>time.txt

C:\mvs380_work\mvshd6>


C:\mvs380>type mvshd.bat
@echo off

if %1. == . goto usage
if not exist %1 goto usage

if %2. == . goto usage
call %~sdp0setpath

set in=%1
set out=%2

call runmvs %MVS380%\jcl\mvshd.jcl %MVS380%\temp.mvs %1 %2 binary ascii
del %MVS380%\temp.mvs

GOTO EXIT
:USAGE
echo mvshd - do a hex dump of a file under MVS
echo Usage mvshd ^<infile^> ^<outfile^>
echo e.g. mvshd world.lmod world.txt
:EXIT

C:\mvs380>


Also, the input file I am using for
this test is very small:

C:\mvs380_work\mvshd6>type in.txt
0123456789

C:\mvs380_work\mvshd6>

Post by '\'Fish\' (David B. Trout)' ***@gmail.com [hercules-390]
variations in the length of time it takes
for Hercules to initialize (startup) or
shutdown across different versions
of Hercules is generally speaking
largely unimportant (unless we're
talking many, many seconds or
minutes perhaps).

That may well be true, but because
of the way I work, I do repeated IPLs,
and quite often only run jobs that
last 1 second, like an IEBGENER,
so I would prefer the behavior of
3.12 which is about 40% faster than
Hyperion, at least when I'm running
small jobs.

BFN. Paul.

['\'Fish\' (David B. Trout)' [e-mail] [hercules-390]]

(OFFLIST)

Try the attached patch against current OFFICIAL 4.0 Hyperion and report back whether it helps, hurts, or makes no difference.

Thanks.

['\'Fish\' (David B. Trout)' [e-mail] [hercules-390]]

Post by '\'Fish\' (David B. Trout)' ***@gmail.com [hercules-390]
(OFFLIST)

<snip>

(Doh!) I guess it's my turn now. :)

Nothing secret folks.

I just didn't want to bother the list with an experimental research patch.

If others want to give it a try that's fine.

[Gregg Levine [e-mail] [hercules-390]]

Hello!
No patch here. This list drops attachments. If you wanted to send a
special patch to the person please do as intended.
-----
Dave W. don't blink, just don't blink, maybe the Doctor can help you,
that is if Sandshoes hasn't forgotten us.....
-----
Gregg C Levine ***@gmail.com
"This signature fought the Time Wars, time and again."


On Mon, Jan 23, 2017 at 1:40 PM, ''Fish' (David B. Trout)'

Post by '\'Fish\' (David B. Trout)' ***@gmail.com [hercules-390]

Post by '\'Fish\' (David B. Trout)' ***@gmail.com [hercules-390]
(OFFLIST)

<snip>
(Doh!) I guess it's my turn now. :)
Nothing secret folks.
I just didn't want to bother the list with an experimental research patch.
If others want to give it a try that's fine.
--
"Fish" (David B. Trout)
Software Development Laboratories
http://www.softdevlabs.com
------------------------------------
------------------------------------
http://groups.yahoo.com/group/hercules-390
http://www.hercules-390.org
------------------------------------
Yahoo Groups Links

['\'Fish\' (David B. Trout)' [e-mail] [hercules-390]]

Post by Gregg Levine ***@gmail.com [hercules-390]
Hello!
No patch here. This list drops attachments. If you wanted
to send a special patch to the person please do as intended.

Yeah, someone else already pointed out that fact which I had completely forgotten about.

I've already sent the patch to him but he claims he's unable to built current Hyperion. Oh well.

If anyone else is interested in it, shoot me an email off-list and I'll send it to you.

Thanks.

[[e-mail] [hercules-390]]

Fish wrote some stuff below:

"Because you are quite right Phil that variations in the length of time it takes for Hercules to initialize (startup) or shutdown across different versions of Hercules is generally speaking largely unimportant (unless we're talking many, many seconds or minutes perhaps).

Benchmarking is both an art and a science and you need to be very careful regarding not only what you're actually measuring but also HOW you're measuring it. It's easy to get sloppy, leading to false conclusions.

..... ( benchmarking programs - CPU intensive )

That's not a half bad idea. In fact it's a rather good one.

BUT... be aware that you'd only be measuring raw instruction emulation speed, not overall emulator performance. Hyperion 4.0's I/O subsystem was significantly enhanced to comply more closely to the architecture for example, whereas 3.12 is still using the older less-architecturally-compliant I/O subsystem design.

The difference in the performance of the two's I/O subsystem wouldn't be reflected in the pure CPU type benchmarks you suggest.

But still, you idea is a good one Phil: try as much as possible to ensure apples are being compared to apples in the comparison of the two versions, which, at least for instruction speed, the aforementioned benchmark programs should certainly accomplish."


So to recap a little:

Paul runs MVS like a command line executable. His comment about slower applies to startup and shutdown of different versions of Hercules only, not the job running time after system is up and running program.

CPU intensive benchmarking doesn't demonstrate differences in I/O re-design:

Try SORT job below, it generates 1,000,000 random values on 80 byte records then sorts them. There is no input required or output either as the output goes to DUMMY. There is a lot of I/O.

Most Turnkey systems have the 2314 sortwork DASD defined already.

//TEST8000 JOB (SETUP),
// 'TEST SORT',
// CLASS=A,
// MSGCLASS=A
//SORTDG EXEC PGM=IEBDG
//SYSPRINT DD SYSOUT=A
//SEQOUT DD UNIT=3390,DCB=(LRECL=80,RECFM=FB,BLKSIZE=8000),
// DSN=&&SORTTEMP,DISP=(,PASS),SPACE=(CYL,(200,20))
//SYSIN DD DATA
DSD OUTPUT=(SEQOUT) ,,
FD NAME=F1,LENGTH=2,STARTLOC=1,FORMAT=RA
FD NAME=F2,LENGTH=4,STARTLOC=3,FORMAT=RA
FD NAME=F3,LENGTH=4,STARTLOC=7,FORMAT=RA
FD NAME=F4,LENGTH=10,STARTLOC=11,FORMAT=ZD,INDEX=1
FD NAME=F5,LENGTH=60,STARTLOC=21
CREATE QUANTITY=1000000,NAME=(F1,F2,F3,F4,F5)
END
/*
//SORT EXEC PGM=SORT,REGION=512K,PARM='MSG=AP'
//SYSOUT DD SYSOUT=A
//SYSUDUMP DD SYSOUT=A
//SYSPRINT DD SYSOUT=A
//SORTLIB DD DSNAME=SYS1.SORTLIB,DISP=SHR
//SORTOUT DD DUMMY,DCB=(BLKSIZE=80,RECFM=F)
//SORTWK01 DD UNIT=2314,SPACE=(CYL,(185,5)),VOL=SER=SORT01
//SORTWK02 DD UNIT=2314,SPACE=(CYL,(185,5)),VOL=SER=SORT02
//SORTWK03 DD UNIT=2314,SPACE=(CYL,(185,5)),VOL=SER=SORT03
//SORTWK04 DD UNIT=2314,SPACE=(CYL,(185,5)),VOL=SER=SORT04
//SORTWK05 DD UNIT=2314,SPACE=(CYL,(185,5)),VOL=SER=SORT05
//SORTWK06 DD UNIT=2314,SPACE=(CYL,(185,5)),VOL=SER=SORT06
//SYSIN DD *
SORT FIELDS=(1,10,CH,A)
RECORD TYPE=F,LENGTH=(80)
END
/*
//SORTIN DD UNIT=3390,DSN=&&SORTTEMP,DISP=SHR

On a ThinkPad 390e - 300 Mhz Pentium II running Hercules 3.07 it takes 11 minutes 34 seconds for the job to run.

Phil

[Gerhard Postpischil [e-mail] [hercules-390]]

Post by ***@hotmail.com [hercules-390]
On a ThinkPad 390e - 300 Mhz Pentium II running Hercules 3.07 it takes
11 minutes 34 seconds for the job to run.

On my Dell desktop, also 3.07, it runs in 8:33

Gerhard Postpischil
Bradford, VT

['Dan Skomsky' [e-mail] [hercules-390]]

Post by Gerhard Postpischil ***@charter.net [hercules-390]

Post by ***@hotmail.com [hercules-390]
On a ThinkPad 390e - 300 Mhz Pentium II running Hercules 3.07 it takes
11 minutes 34 seconds for the job to run.

On my Dell desktop, also 3.07, it runs in 8:33
Gerhard Postpischil
Bradford, VT

On a 3.20 Ghz Quad Core Xeon Dell PowerEdge T20 Server running z/OS under Hyperion. All 2314 references were changed to 3390.

12.45.17 JOB01678 ---- TUESDAY, 24 JAN 2017 ----

12.45.17 JOB01678 IEF677I WARNING MESSAGE(S) FOR JOB TEST8000 ISSUED

12.45.17 JOB01678 $HASP373 TEST8000 STARTED - INIT 5 - CLASS A - SYS SYS1

12.45.17 JOB01678 IEF403I TEST8000 - STARTED - TIME=12.45.17

12.46.04 JOB01678 IEF404I TEST8000 - ENDED - TIME=12.46.04

12.46.04 JOB01678 $HASP395 TEST8000 ENDED

------ JES2 JOB STATISTICS ------

24 JAN 2017 JOB EXECUTION DATE

37 CARDS READ

136 SYSOUT PRINT RECORDS

0 SYSOUT PUNCH RECORDS

8 SYSOUT SPOOL KBYTES

0.79 MINUTES EXECUTION TIME

[[e-mail] [hercules-390]]

Post by Gerhard Postpischil ***@charter.net [hercules-390]

Post by ***@hotmail.com [hercules-390]
On a ThinkPad 390e - 300 Mhz Pentium II running Hercules 3.07 it takes
11 minutes 34 seconds for the job to run.

On my Dell desktop, also 3.07, it runs in 8:33
Gerhard Postpischil
Bradford, VT

HHC01413I Hercules version 4.0.0.8650-gb130229 (4.0.0.8650)
HHC01414I (C) Copyright 1999-2016 by Roger Bowler, Jan Jaeger, and others
HHC01415I Build date: Oct 14 2016 at 10:55:22
HHC01417I Built with: Microsoft Visual C 150030729 1
HHC01417I Build type: Windows MSVC AMD64 host architecture build
HHC01417I Modes: S/370 ESA/390 z/Arch
HHC01417I Max CPU Engines: 64
HHC01417I Using Fish threads Threading Model
HHC01417I Using Error-Checking Mutex Locking Model
HHC01417I With Syncio support
HHC01417I With Shared Devices support
HHC01417I With Dynamic loading support HHC01417I Using shared libraries
HHC01417I With External GUI support
HHC01417I With Partial TCP keepalive support
HHC01417I With IPV6 support
HHC01417I With HTTP Server support
HHC01417I With sqrtl support
HHC01417I Without SIGABEND handler
HHC01417I With CCKD BZIP2 support
HHC01417I With HET BZIP2 support
HHC01417I With ZLIB support
HHC01417I With Regular Expressions support
HHC01417I With Object REXX support
HHC01417I Without Regina REXX support
HHC01417I With Automatic Operator support
HHC01417I Without National Language Support
HHC01417I Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8 hatomics=msvcIntrinsics
HHC01417I Running on: MYPC (Windows-6.2.9200 AMD(R) x64) LP=2, Cores=1, CPUs=1
HHC00018W Hercules is NOT running in elevated mode

My HP desktop with Hercules on an external USB connected hard drive.
I expected the hard drive to bring out I/O slowness over CPU slowness.

Stepname: SORTDG
CPU 0MIN 21.35SEC
SRB 0MIN 01.50SEC
VIRT 56K SYS 204K
elapsed time 00:00:21,67
CPU time 00:00:22,85
Virtual Storage used: 56K Page-in: 0 Page-out: 0
I/O 190 disk had 10,000 blocks written.
Yes, CPU time exceeded duration. Perhaps because of NUMCPU 2 ?
Yes, at 56KB, paging was low.

Stepname: SORT
CPU 0MIN 40.55SEC
SRB 0MIN 16.49SEC
VIRT 288K SYS 208K
elapsed time 00:00:53,88
CPU time 00:00:57,04
Virtual Storage used: 288K Page-in: 0 Page-out: 0
I/O counts ( actually block counts ) by device address
131 4,324
132 8,680
133 8,676
134 8,684
135 9,336
136 5,028
190 10,001
Yes, CPU time exceeded duration. Perhaps because of NUMCPU 2 ?
Yes, at 255KB, paging was low.

Numbers for the JOB:
CPU 1MIN 01.90SEC
SRB 0MIN 17.99SEC
Together, it's: 1 minute 19.89 seconds
Duration was 1 minute 15 seconds.
14.01.02 JOB 723 IEF403I HERC01S - STARTED - TIME=14.01.02
14.01.23 JOB 723 IEFACTRT - Stepname Procstep Program Retcode
14.01.23 JOB 723 HERC01S SORTDG IEBDG RC= 0000
14.02.17 JOB 723 HERC01S SORT SORT RC= 0000
14.02.17 JOB 723 IEF404I HERC01S - ENDED - TIME=14.02.17

Test is still way too CPU intensive for a complete benchmark suite.
Smaller block sizes and not dummying out the output might help?
But smaller block sizes would be even less realistic and cause CPU
usage to shoot up even more.

[[e-mail] [hercules-390]]

It seems that there may be something to the claims that Hyperion is slower vs. Hercules 3.12. I ran the following timings using MVS 3.8 TK3 under Hyperion (fish-git master) and then again under Hercules 3.12. I ran two jobs under MVS: Job #1 is the Stage 1 assembly for MVS system generation, which is a rather large set of macros and runs for a good while. Job #2 is a job that was just posted today to this forum a few posts back, which generates a million records containing random data and then sorts them. I ran these jobs in sequence, not simultaneously, and took the elapsed time from each:

Hyperion 4.0.0
Stage 1 ASM: 101 seconds
Sort: 176 seconds

Hercules 3.12
Stage 1 ASM: 85 seconds (16 seconds less)
Sort: 150 seconds (26 seconds less)

Both runs were on a Dell running Windows 7 with an Intel i7 processor.

Just FYI.

Regards,
Bob

['\'Fish\' (David B. Trout)' [e-mail] [hercules-390]]

***@yahoo.com wrote:

[...]

Yes, CPU time exceeded duration. Perhaps because of NUMCPU 2 ?

<snip>

I don't think it has much to do with the number of CPUs you have, but rather has to do with the way your guest O/S "charges" system overhead CPU time.

Each I/O request that a process/task makes requires a small amount of operating system overhead to service that request (e.g. process the SVC interrupt, perform CCW translation of the channel program, lock I/O buffers, place the request into a queue, process the requests in the queue, issue the SSCH (Start Subchannel) instruction, mark the original task/process non-dispatchable ("waiting for I/O event"), process the eventual I/O interrupt that results from completion of the I/O, mark the original task/process "dispatchable" again, and eventually dispatch it).

The amount of CPU time the operating system consumes performing such internal tasks is typically distributed evenly across ALL tasks/processes.

[[e-mail] [hercules-390]]

Post by '\'Fish\' (David B. Trout)' ***@gmail.com [hercules-390]
[...]

Yes, CPU time exceeded duration. Perhaps because of NUMCPU 2 ?

<snip>
I don't think it has much to do with the number of CPUs you have,
but rather has to do with the way your guest O/S "charges" system
overhead CPU time.

I believe that MVS does a good job accounting for
both CPU time used and step duration.

I switched to NUMCPU 1 but half of my 2314 disks were
on a second CPU channel so the JOB failed to allocate.
Moved all 2314 disks to CPU zero, and
NUMCPU x does make a difference:

Original NUMCPU 2
Stepname: SORTDG
elapsed time 00:00:21,67
CPU time 00:00:22,85
Stepname: SORT
elapsed time 00:00:53,88
CPU time 00:00:57,04

Just tested with NUMCPU 1
Stepname: SORTDG
elapsed time 00:00:19,81
CPU time 00:00:19,27
Stepname: SORT
elapsed time 00:00:41,03
CPU time 00:00:37,76

CPU time now cannot exceed duration and also
comparing the two tests, shows that NUMCPU 2 can
introduce much CPU overhead on MVS 3.8j for the SORT
step and a little CPU overhead for the data generator step.

Post by '\'Fish\' (David B. Trout)' ***@gmail.com [hercules-390]
Each I/O request that a process/task makes requires a small
amount of operating system overhead to service that request
(e.g. process the SVC interrupt, perform CCW translation of
the channel program, lock I/O buffers, place the request into a
queue, process the requests in the queue, issue the SSCH
(Start Subchannel) instruction, mark the original task/process
non-dispatchable ("waiting for I/O event"), process the eventual
I/O interrupt that results from completion of the I/O, mark the
original task/process "dispatchable" again, and eventually dispatch it).
The amount of CPU time the operating system consumes performing
such internal tasks is typically distributed evenly across ALL
tasks/processes.
--
"Fish" (David B. Trout)
Software Development Laboratories
http://www.softdevlabs.com http://www.softdevlabs.com

That is all fine but MVS is accounting for any of that and
as accurate as can be expected.

MVS EXCP counts in this case have nothing to do with
SIO/SIOF because QSAM and BSAM translated to block
counts for SMF counts.

The mentioned MVS gen would be a better benchmark
but real world stuff would be even better.

[[e-mail] [hercules-390]]

wably2 demonstrated what I wished to get across. In the same environment, one version has different results that another for the same workload.

I don't run 3.12 or 4.0 Hercules. I kinda just stuck with 3.07 since it runs on the ancient ThinkPad ( Win2K ). I also think the slow Pentium reveals some impacts which can be muscled out of sight by mucho host processing power.

somitcw wrote:

"My HP desktop with Hercules on an external USB connected hard drive.
I expected the hard drive to bring out I/O slowness over CPU slowness.
...
Test is still way too CPU intensive for a complete benchmark suite.
Smaller block sizes and not dummying out the output might help?
But smaller block sizes would be even less realistic and cause CPU
usage to shoot up even more."

I tested with a USB connected drive also. The ThinkPad 389e has a 1.1 version USB port I think.

Anyway, it took 12 minutes and 4 seconds with the total environment on a USB attached drive vs the 11 minutes and 34 seconds using the laptop's internal drive.

I suspect the 300 Mhz Pentium II is constrained by other things as well. I have run a comparison of CCKD vs CCKD no compression and CKD but can't find it currently.

The IEBDG step surprised me in that it is CPU intensive somewhat ( maybe the random number stuff ). The SORT blocksize is a SORT internal thing, one can't specify the size SORT is going to utilize on it's sortwork packs.

To measure only I/O you would have to have something like a IEBGENER or IEBCOPY from DISK to DISK, or TAPE, but real world is a mix of processing and I/O.

Phil

ps - for those who wish to play with it a little more - records to sort can be increased to 1,600,000 for the 6 2314s ( may have to increase 3390 temp space cylinders ( I don't know - as I originally had this as a tape sort with record lenght 100 ( old Datamation Sort ))). Change sort field to 11 from 1 to have fastest sort time ( sorting an already ordered file ). Changing A to D in sort fields after changing to 11 to have slowest sort time ( I think ) as worst case ( sorting reverse ordered file ).

[[e-mail] [hercules-390]]

Previously I wrote:

"wably2 demonstrated what I wished to get across. In the same environment, one version has different results that another for the same workload."

and fish had written:

"Benchmarking is both an art and a science and you need to be very careful regarding not only what you're actually measuring but also HOW you're measuring it. It's easy to get sloppy, leading to false conclusions."

And sometimes you forget that "RANDOM" means RANDOM. IEBDG generated output will be different each run so the identical sort ( workload ) isn't the same each time.

Unless:

You change the sort field to 11, then the sequence is the same each time whether you keep it A ( ascending ) or change to D ( descending ).

Phil

ps - my original sort used input generated by a pseudo random number generator created to produce the same random sequence for the Datamation Sort challenge so that the workload would be identical for everyone that ran it.

[[e-mail] [hercules-390]]

Under Hercules 3.12 on a I7-6950x (10 core) with Windows 10, using z/OS 2.2 (with 16GB of memory) and all solid state drives, it took overall 5.3 seconds of wall clock, with 1.2 seconds of CPU for the IEBDG step and 1.5 seconds of CPU for the sort step.

I didn't have to do anything to the JCL except change the region from 512K to 0M and change the sortworks to 3390 instead of 2314's.

I had some other stuff running at the time, so maybe that's why it took so long to finish. :)

Brian

['\'Fish\' (David B. Trout)' [e-mail] [hercules-390]]

Brian Westerman wrote:

[...]

Post by ***@SyzygyInc.com [hercules-390]
I had some other stuff running at the time, so maybe that's
why it took so long to finish. :)

Smart aleck! (and show off!)

:)

p.s. NICE box!

[[e-mail] [hercules-390]]

I just built it last week. I'm very happy with it so far.

Brian