Karl Schendel wrote:

It's probably quicker to just poke the relevant host names and IP
addresses into the local hosts file to see if the problem goes away.

That's not something I remembered to suggest but I know he knows to
try that. I'll make sure though. Thanks for the nudge.

--
Roy

UK Ingres User Association Conference 2011 will be on Tuesday June 7 2011.
Put the date in your diary today.

Ingres Forums wrote:

Thank you Bruce. We'll keep you informed of developments.

--
Roy

UK Ingres User Association Conference 2011 will be on Tuesday June 7 2011.
Put the date in your diary today.

Hi Bruce,

Thanks for the information on the GCC tracing, can you point me to some
documentation on that?

I couldn't get the tracing to work, and I thought that the line:

ii.hostname.gcc.*.winsock2_trace_level 5

Might indicate a TCPIP rather than WINTCP connection, which I'm
guessing is what the FTP (PCTCP) client is talking over. I can't find
any evidence of the FTP (PCTCP) product on the clients (there are some
IIFTP.dll files in ingres/bin), which made me start to understand how
much of a fluke this is that it works at all (Is windows picking up this
attempted connection and dealing with it?)

Thanks

Adrian


--
Adrian Williamson

Hi Adrian,
Although the client side is using the FTP TCP interface, over the wire
it is still TCP/IP, so the Ingres 9.2 Windows server can still talk to
it (or any other Ingres client communicating over TCP/IP) using the more
current tcp_ip or wintcp Ingres driver. I assumed that you were using
"tcp_ip" for GCC on the Ingres 9.2 server and had given you the trace
setting for it (..winsock2....). You may instead still have the Ingres
9.2 gcc configured to use "wintcp", which is older than "tcp_ip" but
nevertheless is compatible with any TCP/IP Ingres client. If you are
using "wintcp" on the Ingres 9.2 gcc server (check status: ON for gcc's
wintcp vs tcp_ip in config.dat), the corresponding trace entry to apply
to config.dat is winsock in the place of winsock2 (no harm to have both
in config.dat). The gca_* trace entries remain the same either way.
What this trace will tell you is what the gcc (Ingres/Net) server is
getting from the client and when. These trace settings are not
documented in the standard Ingres documentation, though it does refer to
II_GCA_LOG and II_GCA_TRACE which correspond to the gca_* trace entries
in the config.dat, but are system-wide and affect all processes rather
than can be restricted to specific servers. See KB doc 265114 for a
discussion.

And yes, I think that since you don't have PCTCP product installed,
that somehow (perhaps via IIFTP.exe or IIPCTCP.exe) Windows is picking
up the communications calls and sending them over the wire. Impressive
backward compatibility on Microsoft's part.

Another thing you might try, though I'm not optimistic it will help, is
to switch from using "wintcp" to "tcp_ip" on the Ingres server. This
ideally should be done in one of the Ingres configuration tools such as
CBF; essentially the gcc.*.tcp_ip.status should be ON and
gcc.*.wintcp.status should be OFF. Port for both should be the
same...usually your installation ID. The newer "tcp_ip" Ingres driver
has some performance improvements over "wintcp", though none of the
degree that you are seeing in the poor performance case.

Regards,
Bruce


--
lunbr01

Hi Bruce,

I got a GCA trace for both a fast (Terminal Services) and slow (across
a physical network) execution of the query.

After editing the two files, they pretty much match each other line for
line, the only difference being the 'SLOW' trace takes 3 minutes 17
seconds with the fast one taking 1 minute and 8 seconds.

I've matched the start of the trace against the initial Select
statement through to the last of the sub selects, and it runs pretty
much line for line, with the slow one just taking longer.

The Slow one starts:

(Line 4)
!GCwinsock2_worker_thread TCP_IP: RECV'D, want 2 bytes got 2 bytes
!GCwinsock2_worker_thread TCP_IP: OP_RECV_MSG_LEN get msg, want 669
bytes got 669 bytes
!GCwinsock2_worker_thread TCP_IP: RECV'D, want 669 bytes got 669 bytes
!GCwinsock2_schedule_completion Entered: rq=00000000,
parm_list=00A928B8
!Thu Jan 13 12:03:55 2011 2 GCA_SEND timeout=-1 async
!Thu Jan 13 12:03:55 2011 2 GCA SA_INIT status 00000000 (0)
!Thu Jan 13 12:03:55 2011 2 GCA SA_JUMP status 00000000 (1)
!Thu Jan 13 12:03:55 2011 2 GCA SD_INIT status 00000000 (345)
!Thu Jan 13 12:03:55 2011 2 GCA_SEND msg=GCA_QUERY snd_len=660
eod=1 flow=nor snd_act=true
!Thu Jan 13 12:03:55 2011 2 GCA SD_CKIACK status 00000000 (346)
!Thu Jan 13 12:03:55 2011 2 GCA SD_NEEDTD status 00000000 (347)
!Thu Jan 13 12:03:55 2011 2 GCA SD_DOUSR status 00000000 (349)
!Thu Jan 13 12:03:55 2011 2 GCA SD_SVCHDR status 00000000 (350)
!Thu Jan 13 12:03:55 2011 2 GCA SD_BUFF1 status 00000000 (352)
!Thu Jan 13 12:03:55 2011 send buffering 24 of 24
!Thu Jan 13 12:03:55 2011 2 GCA SD_IS_FMT status 00000000 (357)
!Thu Jan 13 12:03:55 2011 2 GCA SD_SVCUSR status 00000000 (358)
!Thu Jan 13 12:03:55 2011 2 GCA SD_BUFF status 00000000 (360)
!Thu Jan 13 12:03:55 2011 send buffering 660 of 660
!Thu Jan 13 12:03:55 2011 2 GCA SD_CKATTN status 00000000 (372)
!Thu Jan 13 12:03:55 2011 2 GCA SD_NOFLUSH status 00000000
(373)
!Thu Jan 13 12:03:55 2011 2 GCA SA_GOSUB status 00000000 (374)
!Thu Jan 13 12:03:55 2011 2 GCA GC_SEND status 00000000 (509)
!AC 02 00 00 0D 00 00 00 18 00 00 00 94 02 00 00 ................
!05 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 ................
!33 00 00 00 00 00 00 00 80 02 00 00 73 65 6C 65 3...........sele
!63 74 20 63 2E 63 61 73 65 5F 6E 6F 20 61 73 20 ct c.case_no as

With the fast one:

(Line 4)
!GCwinsock2_worker_thread TCP_IP: RECV'D, want 2 bytes got 2 bytes
!GCwinsock2_worker_thread TCP_IP: OP_RECV_MSG_LEN get msg, want 669
bytes got 669 bytes
!GCwinsock2_worker_thread TCP_IP: RECV'D, want 669 bytes got 669 bytes
!GCwinsock2_schedule_completion Entered: rq=00000000,
parm_list=00A928B8
!Thu Jan 13 12:10:43 2011 2 GCA_SEND timeout=-1 async
!Thu Jan 13 12:10:43 2011 2 GCA SA_INIT status 00000000 (0)
!Thu Jan 13 12:10:43 2011 2 GCA SA_JUMP status 00000000 (1)
!Thu Jan 13 12:10:43 2011 2 GCA SD_INIT status 00000000 (345)
!Thu Jan 13 12:10:43 2011 2 GCA_SEND msg=GCA_QUERY snd_len=660
eod=1 flow=nor snd_act=true
!Thu Jan 13 12:10:43 2011 2 GCA SD_CKIACK status 00000000 (346)
!Thu Jan 13 12:10:43 2011 2 GCA SD_NEEDTD status 00000000 (347)
!Thu Jan 13 12:10:43 2011 2 GCA SD_DOUSR status 00000000 (349)
!Thu Jan 13 12:10:43 2011 2 GCA SD_SVCHDR status 00000000 (350)
!Thu Jan 13 12:10:43 2011 2 GCA SD_BUFF1 status 00000000 (352)
!Thu Jan 13 12:10:43 2011 send buffering 24 of 24
!Thu Jan 13 12:10:43 2011 2 GCA SD_IS_FMT status 00000000 (357)
!Thu Jan 13 12:10:43 2011 2 GCA SD_SVCUSR status 00000000 (358)
!Thu Jan 13 12:10:43 2011 2 GCA SD_BUFF status 00000000 (360)
!Thu Jan 13 12:10:43 2011 send buffering 660 of 660
!Thu Jan 13 12:10:43 2011 2 GCA SD_CKATTN status 00000000 (372)
!Thu Jan 13 12:10:43 2011 2 GCA SD_NOFLUSH status 00000000
(373)
!Thu Jan 13 12:10:43 2011 2 GCA SA_GOSUB status 00000000 (374)
!Thu Jan 13 12:10:43 2011 2 GCA GC_SEND status 00000000 (509)
!AC 02 00 00 0D 00 00 00 18 00 00 00 94 02 00 00 ................
!05 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 ................
!33 00 00 00 00 00 00 00 80 02 00 00 73 65 6C 65 3...........sele
!63 74 20 63 2E 63 61 73 65 5F 6E 6F 20 61 73 20 ct c.case_no as

The slow session then commences the first subselect 22 seconds later as
follows:

(Line 2032)
!Thu Jan 13 12:04:17 2011 2 GCA GC_SEND status 00000000 (509)
!B9 00 00 00 0D 00 00 00 18 00 00 00 A1 00 00 00 ................
!05 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 ................
!15 00 00 00 00 00 00 00 08 00 00 00 06 00 31 30 ..............10
!32 34 38 35 33 00 00 00 00 00 00 00 79 00 00 00 24853.......y...
!73 65 6C 65 63 74 20 73 63 2E 64 69 73 63 69 70 select sc.discip
!6C 69 6E 65 5F 63 6F 64 65 20 61 73 20 76 5F 64 line_code as v_d
!69 73 63 69 70 6C 69 6E 65 5F 63 6F 64 65 2C 20 iscipline_code,
!73 63 2E 61 6C 6C 6F 63 61 74 65 64 5F 74 6F 20 sc.allocated_to
!61 73 20 76 5F 61 6C 6C 6F 63 61 74 65 64 5F 74 as v_allocated_t
!6F 20 66 72 6F 6D 20 73 75 62 5F 63 61 73 65 20 o from sub_case
!73 63 20 77 68 65 72 65 20 73 63 2E 63 61 73 65 sc where sc.case
!5F 6E 6F 3D 20 7E 56 20 00 _no= ~V .
!Thu Jan 13 12:04:17 2011 2 GCA GC_ASYNC status 00000000 (510)
!GCwinsock2 TCP_IP: GCC_RECEIVE
!GCwinsock2 TCP_IP: GCC_RECEIVE, want 2 bytes got 0 bytes
!Thu Jan 13 12:04:17 2011 2 GCA SD_MORE status 00000000 (511)
!Thu Jan 13 12:04:17 2011 2 GCA SA_RETURN status 00000000 (512)
!Thu Jan 13 12:04:17 2011 2 GCA SA_IFERR status 00000000 (375)
!Thu Jan 13 12:04:17 2011 2 GCA SD_DONE status 00000000 (377)
!Thu Jan 13 12:04:17 2011 2 GCA SA_COMPLETE status 00000000
(378)
!Thu Jan 13 12:04:17 2011 2 GCA_COMPLETE 8 status=00000000
!Thu Jan 13 12:04:17 2011 2 GCA_COMPLETE 8 completing
!Thu Jan 13 12:04:17 2011 2 GCA SA_IFERR status 00000000 (395)
!Thu Jan 13 12:04:17 2011 2 GCA SA_RECV_DONE status 00000000
(396)
(Line 2056)

With the fast select starting the same frst subselect 13 econds later:

(Line 2031)
!Thu Jan 13 12:10:56 2011 2 GCA GC_SEND status 00000000 (509)
!B9 00 00 00 0D 00 00 00 18 00 00 00 A1 00 00 00 ................
!05 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 ................
!15 00 00 00 00 00 00 00 08 00 00 00 06 00 31 30 ..............10
!32 34 38 35 33 00 00 00 00 00 00 00 79 00 00 00 24853.......y...
!73 65 6C 65 63 74 20 73 63 2E 64 69 73 63 69 70 select sc.discip
!6C 69 6E 65 5F 63 6F 64 65 20 61 73 20 76 5F 64 line_code as v_d
!69 73 63 69 70 6C 69 6E 65 5F 63 6F 64 65 2C 20 iscipline_code,
!73 63 2E 61 6C 6C 6F 63 61 74 65 64 5F 74 6F 20 sc.allocated_to
!61 73 20 76 5F 61 6C 6C 6F 63 61 74 65 64 5F 74 as v_allocated_t
!6F 20 66 72 6F 6D 20 73 75 62 5F 63 61 73 65 20 o from sub_case
!73 63 20 77 68 65 72 65 20 73 63 2E 63 61 73 65 sc where sc.case
!5F 6E 6F 3D 20 7E 56 20 00 _no= ~V .
!Thu Jan 13 12:10:57 2011 2 GCA GC_ASYNC status 00000000 (510)
!GCwinsock2 TCP_IP: GCC_RECEIVE
!GCwinsock2 TCP_IP: GCC_RECEIVE, want 2 bytes got 0 bytes
!Thu Jan 13 12:10:57 2011 2 GCA SD_MORE status 00000000 (511)
!Thu Jan 13 12:10:57 2011 2 GCA SA_RETURN status 00000000 (512)
!Thu Jan 13 12:10:57 2011 2 GCA SA_IFERR status 00000000 (375)
!Thu Jan 13 12:10:57 2011 2 GCA SD_DONE status 00000000 (377)
!Thu Jan 13 12:10:57 2011 2 GCA SA_COMPLETE status 00000000
(378)
!Thu Jan 13 12:10:57 2011 2 GCA_COMPLETE 8 status=00000000
!Thu Jan 13 12:10:57 2011 2 GCA_COMPLETE 8 completing
!Thu Jan 13 12:10:57 2011 2 GCA SA_IFERR status 00000000 (395)
!Thu Jan 13 12:10:57 2011 2 GCA SA_RECV_DONE status 00000000
(396)
(Line 2055)

After the 63rd nested select in the slow session we're at:

(line 27875)
!5F 6E 6F 3D 20 7E 56 20 00 _no= ~V .
!Thu Jan 13 12:07:10 2011 2 GCA GC_ASYNC status 00000000 (510)
!GCwinsock2 TCP_IP: GCC_RECEIVE
!GCwinsock2 TCP_IP: GCC_RECEIVE, want 2 bytes got 0 bytes
!Thu Jan 13 12:07:10 2011 2 GCA SD_MORE status 00000000 (511)
!Thu Jan 13 12:07:10 2011 2 GCA SA_RETURN status 00000000 (512)
!Thu Jan 13 12:07:10 2011 2 GCA SA_IFERR status 00000000 (375)
!Thu Jan 13 12:07:10 2011 2 GCA SD_DONE status 00000000 (377)
!Thu Jan 13 12:07:10 2011 2 GCA SA_COMPLETE status 00000000
(378)
!Thu Jan 13 12:07:10 2011 2 GCA_COMPLETE 8 status=00000000
!Thu Jan 13 12:07:10 2011 2 GCA_COMPLETE 8 completing
!Thu Jan 13 12:07:10 2011 2 GCA SA_IFERR status 00000000 (395)
!Thu Jan 13 12:07:10 2011 2 GCA SA_RECV_DONE status 00000000
(396)
!48 00 00 00 15 00 00 00 18 00 00 00 30 00 00 00 H...........0...

and for the fast session:

(line 27861)
!5F 6E 6F 3D 20 7E 56 20 00 _no= ~V .
!Thu Jan 13 12:11:51 2011 2 GCA GC_ASYNC status 00000000 (510)
!GCwinsock2 TCP_IP: GCC_RECEIVE
!GCwinsock2 TCP_IP: GCC_RECEIVE, want 2 bytes got 0 bytes
!Thu Jan 13 12:11:51 2011 2 GCA SD_MORE status 00000000 (511)
!Thu Jan 13 12:11:51 2011 2 GCA SA_RETURN status 00000000 (512)
!Thu Jan 13 12:11:51 2011 2 GCA SA_IFERR status 00000000 (375)
!Thu Jan 13 12:11:51 2011 2 GCA SD_DONE status 00000000 (377)
!Thu Jan 13 12:11:51 2011 2 GCA SA_COMPLETE status 00000000
(378)
!Thu Jan 13 12:11:51 2011 2 GCA_COMPLETE 8 status=00000000
!Thu Jan 13 12:11:51 2011 2 GCA_COMPLETE 8 completing
!Thu Jan 13 12:11:51 2011 2 GCA SA_IFERR status 00000000 (395)
!Thu Jan 13 12:11:51 2011 2 GCA SA_RECV_DONE status 00000000
(396)
!48 00 00 00 15 00 00 00 18 00 00 00 30 00 00 00 H...........0...


--
Adrian Williamson

....So I can't see any Ingres reason for the delay, it seems to be
something to do with Windows Networking and the w4gl dev V2 network
layer, given that the same nested query runs against a 6.4/06 server on
a 15 year old IBM AIX box (without trace overhead) in five seconds,
against Windows it takes 35 seconds.

Under OpenROAD 2006 it's sub second.

I can't spend any more time on this now, but thanks for the trace
information, it was a relief to get it working and it was also somewhat
reassuring that the two seperate session traces were nearly identicle
apart from the time drift.

Regards,

Adrian
PS The trace wouldn't work for me with a path i.e. 'c:\temp\GCA.LOG'
didn't work but 'GCA.LOG' did.


--
Adrian Williamson

Sorry about the mistake in the path filename for the trace file. On
Windows, in the config.dat, the back-slash must be doubled (ie,
escaped)...eg, 'c:\\temp\\gca.log'.

It does appear to be some problem in the old Windows networking via the
old TCP_FTP Ingres driver, though it's odd that it works fine against
the old IBM AIX box. Like you said, the only real diff seems to be the
time drift. Hence, it is not a DNS lookup type problem, which would
only affect connection setup time. The problem is more likely something
to do with the TCP receive window size or timing in the client polling
of the network...hard to say. One last thought: If your subselects are
each sending more than 1 packet back to the front end, you might be
getting hit by one of the TCP "performance" algorithms; specifically,
the Naegle algorithm tries to optimize overall network traffic by
delaying certain packets for up to 200 milliseconds. This can seriously
degrade performance if a lot of network messages are going back and
forth. The Naegle algorithm is ON by default in Windows, but may not
have been on your AIX server. In Ingres 9.3.1, an option was added to
Ingres protocol "tcp_ip" to turn off the Naegle algorithm for network
sessions by setting Ingres variable II_WINSOCK2_NODELAY to ON (ie, run
"ingsetenv II_WINSOCK2_NODELAY ON" in the Ingres server installation).
In Ingres 10, this is the default. In Ingres 9.2 and earlier, it is not
available as an option. This option was implemented because we saw some
small performance benefit in batch-like runs and overall it never seemed
to hurt performance. We never saw a huge performance difference, which
is what you are looking for. However, it's an option you might want to
try at some point.

Regards,

Bruce


--
lunbr01

Hi Adrian.

Can you clarify what you mean by terminal services. Are you saying the setup is as follows: -

Box A = Windows Server + Ingres 9.2 DBMS + W4GLv2 (6.3 stack)
Box B = W4GLv2 (6.3 stack)

1/ if you use TS and Logon to Box A - response time is 5 seconds ?
2/ if you Logon to Box B - response time is 35 seconds ?

It's been a while since i've used the W4GLv2 but I seem to recall there was a simple sql monitor (tmsql/tmproc or something?) available for it that used the ingres net stack.

First point would be to see if you can find this program and if it connects up ok. Next would be to use this program (and so remove any complexitiesof W4GL) to understand if what you are seeing is a network traffic delay or something else ! If both 'A' and 'B' scenarios are equivalent on connectsthen we're talking about delay in transmission or the result sets are being stored somewhere slower in scenario 'B'.

What suprises me is the TS Box A scenario.. you're using W4GLv2 which is then using the 6.3 ingres stack to communicate to the 9.2 server - but you see no delays...

Enjoy and post what you find

Gary

Hi Bruce,

I'm very pleased to report that after upgrading from 9.2 to 9.3 the
II_WINSOCK2_NODELAY attribute has restored and exceeded the applications
previous performance.

Happy campers all round.

Thanks for solving this for us.

Adrian


--
Adrian Williamson