aws/aws-sdk-cpp

Lex v2 not working (i.e. incredibly slow) on debian 12

davehorton opened this issue · 19 comments

Describe the bug

Is anyone having trouble making lex v2 runtime work on debian 12? I have previously been running aws-sdk-cpp tag 1.8.129 on debian 11 and it worked fine. Now on debian 12 I have update to the latest (1.11.217) and things are not working at all. I am connection ok and sending audio, but not getting any responses back other than a heartbeat. No transcripts and no intents.

I also had trouble with a similar upgrade with aws_transcribe, and ended up having to switch to using the websocket api instead of the sdk. Is there a websocket api for lex?

Expected Behavior

I expected to receive messages from lex v2 - intents and transcriptions.

Current Behavior

Here is a trace file showing what I received.
aws_sdk_2023-12-05-01.log

Reproduction Steps

debian 12 and using

Possible Solution

No response

Additional Information/Context

No response

AWS CPP SDK version used

1.11.217

Compiler and Version used

gcc (Debian 12.2.0-14) 12.2.0

Operating System and version

Debian 12

I can add more details, and more strange results. Today I tested with a longer call -- I connected to lex (the sample flight book bot) and said "I'd like to book a flight". For about a minute no responses other than heartbeats, then a full minute or more later I get a transcript (i'd like to book a flight), followed by a message indicating an internal error, see below

2023-12-05 14:04:39.884140 sessionId 98748812-0920-476d-9fb4-5ee2c215d216, botId UVDS8FV0YK, alias PDOU6XC85F, region us-east-1, locale en_US
2023-12-05 14:04:39.884140 starting conversation
2023-12-05 14:04:39.884140 got stream ready
2023-12-05 14:05:00.024148 recv heartbeat
2023-12-05 14:05:20.024148 recv heartbeat
2023-12-05 14:05:40.024146 recv heartbeat
2023-12-05 14:06:00.024147 recv heartbeat
2023-12-05 14:06:02.204138 {"transcript":"i'd like to book a flight","eventId":"RESPONSE-11"}.
2023-12-05 14:06:14.844137 {"message":"The server encountered an internal error while processing the request"}

In case its possible to retrieve any logs from the server side the conversation url was

/bots/UVDS8FV0YK/botAliases/PDOU6XC85F/botLocales/en_US/sessions/98748812-0920-476d-9fb4-5ee2c215d216/conversation

Again, this code worked fine on earlier versions of the sdk and debian.

Here is another example. I placed a call, immediately said "I'd like to book a flight" and after about one minute and 20 seconds later I got the transcript followed by the intent. What could be accounting for this delay?

2023-12-05 15:05:08.637147 98.73% [DEBUG] aws_lex_glue.cpp:338 GStreamer 0x7f335c001130 sessionId 74b99e76-a681-463c-b6a6-a98fbf1687b7, botId UVDS8FV0YK, alias PDOU6XC85F, region us-east-1, locale en_US
2023-12-05 15:05:08.637147 98.73% [DEBUG] aws_lex_glue.cpp:431 GStreamer 0x7f335c001130 starting conversation
2023-12-05 15:05:08.637147 98.73% [INFO] aws_lex_glue.cpp:353 GStreamer 0x7f335c001130 using tts so audio packets will be discarded
2023-12-05 15:05:08.637147 98.73% [DEBUG] aws_lex_glue.cpp:409 GStreamer 0x7f335c001130 got stream ready
2023-12-05 15:05:08.637147 98.73% [DEBUG] switch_rtp.c:7503 Correct audio ip/port confirmed.
2023-12-05 15:05:08.637147 98.73% [DEBUG] switch_core_io.c:448 Setting BUG Codec PCMU:0
2023-12-05 15:05:08.757148 98.73% [DEBUG] aws_lex_glue.cpp:210 GStreamer 0x7f335c001130 recv heartbeat
2023-12-05 15:05:13.637147 97.33% [DEBUG] switch_rtp.c:6933 Correct audio RTCP ip/port confirmed.
2023-12-05 15:05:28.757146 95.07% [DEBUG] aws_lex_glue.cpp:210 GStreamer 0x7f335c001130 recv heartbeat
2023-12-05 15:05:48.757149 95.00% [DEBUG] aws_lex_glue.cpp:210 GStreamer 0x7f335c001130 recv heartbeat
2023-12-05 15:06:08.757148 94.57% [DEBUG] aws_lex_glue.cpp:210 GStreamer 0x7f335c001130 recv heartbeat
2023-12-05 15:06:28.757148 95.13% [DEBUG] aws_lex_glue.cpp:210 GStreamer 0x7f335c001130 recv heartbeat
2023-12-05 15:06:35.097146 94.57% [INFO] mod_aws_lex.c:21 json payload for type lex::transcription: {"transcript":"i'd like to book a flight","eventId":"RESPONSE-11"}.
2023-12-05 15:06:36.117147 94.40% [INFO] mod_aws_lex.c:21 json payload for type lex::intent: {"eventId":"RESPONSE-12","sessionId":"74b99e76-a681-463c-b6a6-a98fbf1687b7","sessionState":{"dialogAction":{"type":"ElicitSlot","slotToElicit":"FrequentFlyerNumber"},"intent":{"name":"BookAFlight","slots":{"CardExpiryDate":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"CardLast4Digits":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"CardLast4DigitsConfirmation":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"CardNumber":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"CardNumberConfirmation":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"DepartureCity":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"DepartureDate":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"DestinationCity":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"FlightSelected":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"FrequentFlyerNumber":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"NumberOfTravellers":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"NumberOfTravellersInWords":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"PreferredDepartureTime":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"PreferredReturnDepartureTime":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"ReturnDate":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"SecurityCode":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"TripType":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}}},"intentState":"InProgress","confirmationState":"None"},"activeContexts":[],"attributes":{}},"requestAttributes":{},"interpretations":[{"confidence":0.95,"sentiment":{"type":"","score":{"positive":0,"negative":0,"neutral":0,"mixed":0}},"intent":{"name":"BookAFlight","slots":{"CardExpiryDate":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"CardLast4Digits":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"CardLast4DigitsConfirmation":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"CardNumber":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"CardNumberConfirmation":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"DepartureCity":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"DepartureDate":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"DestinationCity":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"FlightSelected":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"FrequentFlyerNumber":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"NumberOfTravellers":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"NumberOfTravellersInWords":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"PreferredDepartureTime":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"PreferredReturnDepartureTime":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"ReturnDate":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"SecurityCode":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"TripType":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}}},"intentState":"InProgress","confirmationState":"None"}},{"confidence":0.64,"sentiment":{"type":"","score":{"positive":0,"negative":0,"neutral":0,"mixed":0}},"intent":{"name":"CancelFlightReservation","slots":{"FlightBookingDate":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"FlightConfirmationNumber":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"PassengerLastName":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"PassengerLastNameSpellOut":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}}},"intentState":"","confirmationState":""}},{"confidence":0.61,"sentiment":{"type":"","score":{"positive":0,"negative":0,"neutral":0,"mixed":0}},"intent":{"name":"GetFlightStatus","slots":{"DepartureCity":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"DepartureTime":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"DestinationCity":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"FlightNumber":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"FlightNumberConfirmation":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}}},"intentState":"","confirmationState":""}},{"confidence":0.56,"sentiment":{"type":"","score":{"positive":0,"negative":0,"neutral":0,"mixed":0}},"intent":{"name":"RescheduleTrip","slots":{"FlightConfirmationNumber":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"NewDepartureDate":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"PassengerLastName":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"PassengerLastNameSpellOut":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}}},"intentState":"","confirmationState":""}},{"confidence":0.51,"sentiment":{"type":"","score":{"positive":0,"negative":0,"neutral":0,"mixed":0}},"intent":{"name":"CheckReservationDetails","slots":{"FlightConfirmationNumber":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}},"PassengerLastName":{"value":{"originalValue":"","interpretedValue":"","resolvedValues":[]}}},"intentState":"","confirmationState":""}}]}.
2023-12-05 15:06:36.117147 94.40% [INFO] mod_aws_lex.c:21 json payload for type lex::text_response: {"eventId":"RESPONSE-13","messages":[{"msg":"I see you have a frequent flyer account with us. Can you confirm your frequent flyer number?","type":"PlainText"}]}.
2023-12-05 15:06:37.157146 94.20% [DEBUG] switch_ivr.c:632 sofia/drachtio_mrf/nobody@10.0.130.115:5070 Command Execute [depth=1] playback(/tmp/tts-0e627eab-1b03-42bb-a752-68f42acb9cf48a77658b-c678-483d-9fd4-d40423

Note: developing to lex v2 is hampered by the fact I have not found any examples in this repo or elsewhere. If there is a working example I could test with (similar to the getTranscript example for aws transcribe) this would be very helpful for developers

jmklix commented

I'm working on creating a sample using lexv2. I will post it here when I have that finished

great, many thanks! In the meantime let me know if I can do anything to provide additional information

just checking in....anything new on this?

anything new on this? I'm blocked by this so if I can do anything to gather information please let me know

HERE IS A SAMPLE PROGRAM SHOWING THE PROBLEM

@jmklix I have created a sample program that shows the problem. Please have a look when you get a chance.

This program uses the lex api to stream 2 minutes of audio to a lex bot (I tested using the HotelBot). The caller immediately says "I would like to book a flight". When run on Debian 11, a transcript is returned about 6 seconds after the start of the call. When run on Debian 12 the same transcript is returned after 2 minutes (!).

If I am doing something wrong, it should be easy for you to see in the sample program, but as far as I can tell I am just calling the apis.

My tests were run on AWS in us-east-1

  • debian-11 AMI: ami-0f63aa666117f7cc1
  • debian-12 AMI: ami-058bd2d568351da34

anything new on this? Have you had a chance to use the sample program I provided to debug? Complete instructions for compiling and running the sample program are included in the README of the repo linked above..

Hi @davehorton ,

I've been working on transcribe streaming issues we have.
While I'm still preparing a PR, for the performance degradation issue, could you please try to increase the buffer size here?

const size_t DEFAULT_BUF_SIZE = 1024;

I'd suggest setting 8096 or even bigger buffer (the one that will be big enough to contain the whole encoded http2 frame), that's one of the reasons of a poor performance today.
There are some additional issues regarding jittering and final frame processing which I'm also trying to address, but it would be great if the buffer size increase will fix the performance for view.

Best regards,
Sergey

hi @SergeyRyabinin we ran our test on debian 12 with your suggested changes

  • After changing the buffer size to 8096: after 21 secs we received transcript
  • after changing the buffer size to 16192: after 13 secs we received transcript

So the changes still had a positive impact. However, still much slower than debian 11 and not able to be used in production.

@SergeyRyabinin is there a PR on this yet? I've been blocked releasing an upgrade to my product for months now, and this seems like a fairly significant bug, for streaming transcription essentially to not work on the latest debian release.

Anything new on this @jmklix @SergeyRyabinin

@jmklix @SergeyRyabinin is there any intent to fix this? It seems like a rather major bug to me, unless lex v2 is not a priority for AWS

Hi @davehorton ,

Please sorry for a delay in reply.
I have merged a change for TranscribeStreaming / HTTP2 stream processing within the SDK:
#2816

it improves the performance of http2 streaming for transcribe, however, I'm still yet to add a similar integration test for the lexv2 streaming.

Best regards,
Sergey

hi @SergeyRyabinin thanks for the update. I had experienced the problem with http2 streaming for transcribe as well -- I was forced to change to the websocket interface on debian 12 because http2 api was basically non-functional.

That means, though, that I should at least be able to test that PR for lex v2 transcribe and let you know if it solves my issue there. I will do that and provide results here.

@SergeyRyabinin I tested aws-sdk-cpp 1.11.283 and it seems to have resolved the issue for both aws transcribe and aws lex. I will do a bit of further testing before closing this issue. Many thanks

This issue does seem to be fixed in 1.11.283. Thanks!

This issue is now closed. Comments on closed issues are hard for our team to see.
If you need more assistance, please open a new issue that references this one.