Unexpected provisioned throughput increase #135

Closed
OXYAMINE opened this Issue Mar 27, 2014 · 8 comments

Projects

None yet

2 participants

@OXYAMINE

I can see unexpected provisioned throughput increase performed by dynamic-dynamoDB script. Looking at this behavior second day.
There is a table configured like this:

writes-upper-threshold: 80
writes-lower-threshold: 30
increase-writes-with: 10
decrease-writes-with: 30
increase-writes-unit: percent
decrease-writes-unit: percent
min-provisioned-writes: 5
max-provisioned-writes: 500

And there is this in logs:

2014-03-27 17:05:45,815 - dynamic-dynamodb - INFO - SW_Chat - Consumed read units: 8%
2014-03-27 17:05:45,838 - dynamic-dynamodb - INFO - SW_Chat - Read throttle count: 0
2014-03-27 17:05:45,888 - dynamic-dynamodb - INFO - SW_Chat - Consumed write units: 74%
2014-03-27 17:05:45,907 - dynamic-dynamodb - INFO - SW_Chat - Write throttle count: 260
2014-03-27 17:05:45,908 - dynamic-dynamodb - INFO - SW_Chat - Changing provisioning to 13 read units and 176 write units
2014-03-27 17:05:46,137 - dynamic-dynamodb - INFO - SW_Chat - Provisioning updated to 13 reads and 176 writes
2014-03-27 17:10:46,383 - dynamic-dynamodb - INFO - SW_Chat - Consumed read units: 8%
2014-03-27 17:10:46,406 - dynamic-dynamodb - INFO - SW_Chat - Read throttle count: 0
2014-03-27 17:10:46,465 - dynamic-dynamodb - INFO - SW_Chat - Consumed write units: 54%
2014-03-27 17:10:46,495 - dynamic-dynamodb - INFO - SW_Chat - Write throttle count: 2990
2014-03-27 17:10:46,496 - dynamic-dynamodb - INFO - SW_Chat - Changing provisioning to 13 read units and 194 write units
2014-03-27 17:10:46,825 - dynamic-dynamodb - INFO - SW_Chat - Provisioning updated to 13 reads and 194 writes
2014-03-27 17:15:47,043 - dynamic-dynamodb - INFO - SW_Chat - Consumed read units: 16%
2014-03-27 17:15:47,071 - dynamic-dynamodb - INFO - SW_Chat - Read throttle count: 0
2014-03-27 17:15:47,121 - dynamic-dynamodb - INFO - SW_Chat - Consumed write units: 50%
2014-03-27 17:15:47,143 - dynamic-dynamodb - INFO - SW_Chat - Write throttle count: 2947
2014-03-27 17:15:47,144 - dynamic-dynamodb - INFO - SW_Chat - Changing provisioning to 13 read units and 214 write units
2014-03-27 17:15:47,346 - dynamic-dynamodb - INFO - SW_Chat - Provisioning updated to 13 reads and 214 writes
2014-03-27 17:20:47,600 - dynamic-dynamodb - INFO - SW_Chat - Consumed read units: 8%
2014-03-27 17:20:47,633 - dynamic-dynamodb - INFO - SW_Chat - Read throttle count: 0
2014-03-27 17:20:47,692 - dynamic-dynamodb - INFO - SW_Chat - Consumed write units: 33%
2014-03-27 17:20:47,717 - dynamic-dynamodb - INFO - SW_Chat - Write throttle count: 3716
2014-03-27 17:20:47,717 - dynamic-dynamodb - INFO - SW_Chat - Changing provisioning to 13 read units and 236 write units
2014-03-27 17:20:48,015 - dynamic-dynamodb - INFO - SW_Chat - Provisioning updated to 13 reads and 236 writes
2014-03-27 17:25:48,249 - dynamic-dynamodb - INFO - SW_Chat - Consumed read units: 16%
2014-03-27 17:25:48,269 - dynamic-dynamodb - INFO - SW_Chat - Read throttle count: 0
2014-03-27 17:25:48,331 - dynamic-dynamodb - INFO - SW_Chat - Consumed write units: 35%
2014-03-27 17:25:48,358 - dynamic-dynamodb - INFO - SW_Chat - Write throttle count: 3594
2014-03-27 17:25:48,359 - dynamic-dynamodb - INFO - SW_Chat - Changing provisioning to 13 read units and 260 write units
2014-03-27 17:25:48,702 - dynamic-dynamodb - INFO - SW_Chat - Provisioning updated to 13 reads and 260 writes
2014-03-27 17:30:48,948 - dynamic-dynamodb - INFO - SW_Chat - Consumed read units: 16%
2014-03-27 17:30:48,978 - dynamic-dynamodb - INFO - SW_Chat - Read throttle count: 22
2014-03-27 17:30:49,027 - dynamic-dynamodb - INFO - SW_Chat - Consumed write units: 35%
2014-03-27 17:30:49,050 - dynamic-dynamodb - INFO - SW_Chat - Write throttle count: 3600
2014-03-27 17:30:49,051 - dynamic-dynamodb - INFO - SW_Chat - Changing provisioning to 13 read units and 286 write units
2014-03-27 17:30:49,278 - dynamic-dynamodb - INFO - SW_Chat - Provisioning updated to 13 reads and 286 writes
2014-03-27 17:35:49,496 - dynamic-dynamodb - INFO - SW_Chat - Consumed read units: 8%
2014-03-27 17:35:49,525 - dynamic-dynamodb - INFO - SW_Chat - Read throttle count: 0
2014-03-27 17:35:49,587 - dynamic-dynamodb - INFO - SW_Chat - Consumed write units: 39%
2014-03-27 17:35:49,607 - dynamic-dynamodb - INFO - SW_Chat - Write throttle count: 3374
2014-03-27 17:35:49,607 - dynamic-dynamodb - INFO - SW_Chat - Changing provisioning to 13 read units and 315 write units
2014-03-27 17:35:49,775 - dynamic-dynamodb - INFO - SW_Chat - Provisioning updated to 13 reads and 315 writes
2014-03-27 17:40:50,015 - dynamic-dynamodb - INFO - SW_Chat - Consumed read units: 16%
2014-03-27 17:40:50,046 - dynamic-dynamodb - INFO - SW_Chat - Read throttle count: 15
2014-03-27 17:40:50,096 - dynamic-dynamodb - INFO - SW_Chat - Consumed write units: 40%
2014-03-27 17:40:50,122 - dynamic-dynamodb - INFO - SW_Chat - Write throttle count: 3185
2014-03-27 17:40:50,122 - dynamic-dynamodb - INFO - SW_Chat - Changing provisioning to 13 read units and 347 write units
2014-03-27 17:40:50,380 - dynamic-dynamodb - INFO - SW_Chat - Provisioning updated to 13 reads and 347 writes
2014-03-27 17:45:50,586 - dynamic-dynamodb - INFO - SW_Chat - Consumed read units: 8%
2014-03-27 17:45:50,610 - dynamic-dynamodb - INFO - SW_Chat - Read throttle count: 70
2014-03-27 17:45:50,671 - dynamic-dynamodb - INFO - SW_Chat - Consumed write units: 40%
2014-03-27 17:45:50,694 - dynamic-dynamodb - INFO - SW_Chat - Write throttle count: 2808
2014-03-27 17:45:50,695 - dynamic-dynamodb - INFO - SW_Chat - Changing provisioning to 13 read units and 382 write units
2014-03-27 17:45:50,966 - dynamic-dynamodb - INFO - SW_Chat - Provisioning updated to 13 reads and 382 writes
2014-03-27 17:50:51,534 - dynamic-dynamodb - INFO - SW_Chat - Consumed read units: 8%
2014-03-27 17:50:51,677 - dynamic-dynamodb - INFO - SW_Chat - Read throttle count: 0
2014-03-27 17:50:51,754 - dynamic-dynamodb - INFO - SW_Chat - Consumed write units: 39%
2014-03-27 17:50:51,844 - dynamic-dynamodb - INFO - SW_Chat - Write throttle count: 2675
2014-03-27 17:50:51,845 - dynamic-dynamodb - INFO - SW_Chat - Changing provisioning to 13 read units and 421 write units
2014-03-27 17:50:52,931 - dynamic-dynamodb - INFO - SW_Chat - Provisioning updated to 13 reads and 421 writes
2014-03-27 17:55:53,168 - dynamic-dynamodb - INFO - SW_Chat - Consumed read units: 8%
2014-03-27 17:55:53,186 - dynamic-dynamodb - INFO - SW_Chat - Read throttle count: 0
2014-03-27 17:55:53,240 - dynamic-dynamodb - INFO - SW_Chat - Consumed write units: 44%
2014-03-27 17:55:53,257 - dynamic-dynamodb - INFO - SW_Chat - Write throttle count: 1706
2014-03-27 17:55:53,257 - dynamic-dynamodb - INFO - SW_Chat - Changing provisioning to 13 read units and 464 write units
2014-03-27 17:55:53,514 - dynamic-dynamodb - INFO - SW_Chat - Provisioning updated to 13 reads and 464 writes

The question is why is it increases the limit if consumption is much, much less than writes-upper-threshold and continues to decrease?
Actually this cost us a lot of money and makes to think how reliable dynamic-dynamoDB is.

@sebdah
Owner
sebdah commented Mar 28, 2014

Thanks for the report. However, I would need the following to see why the provisioning is increased:

  • Full configuration file
  • (Preferably) Log file with debug logging enabled

It looks like you have a lot of throttled write requests, maybe they are the cause?

@sebdah sebdah self-assigned this Mar 28, 2014
@sebdah
Owner
sebdah commented Mar 28, 2014

(accidentally removed comment)..:

@zgrega wrote:

Hello,

I have also seen this problem. In my case it happened during write peek.
It seems that dynamic dynamodb relies two much on write throttled requests.
In my understanding throttled requests are gone, application should take
care them. In this case you should only check write requests % in my
opinion. This would then prevent scaling up.

Brg

Thanks for the report. However, I would need the following to see why the
provisioning is increased:

  • Full configuration file
  • (Preferably) Log file with debug
    logginghttp://dynamic-dynamodb.readthedocs.org/en/latest/configuration_options.html#logging-configurationenabled

It looks like you have a lot of throttled write requests, maybe they are
the cause?

@sebdah
Owner
sebdah commented Mar 28, 2014

Interesting @zgrega. I was not expecting throttling to be considered unless explicitly configured. Will look at what might cause this.

@sebdah
Owner
sebdah commented Mar 28, 2014

I have located a part in the code that seems to be guilty for this behaviour. The code fix in 50d7443 should make dynamic-dynamodb skip throttling unless it is configured explicitly (with a value higher than 0). A beta version of this is included in version 1.10.2b4. Please install it with the following command and verify if the behaviour still exists.

pip install dynamic-dynamodb==1.10.2b4
@sebdah sebdah added this to the 1.10.x milestone Mar 28, 2014
@sebdah sebdah added a commit that referenced this issue Mar 28, 2014
@sebdah Added release notes for #134 and #135 9c97b7f
@sebdah
Owner
sebdah commented Mar 29, 2014

This has now been released in version 1.10.2. Thanks for the bug report!

@sebdah sebdah closed this Mar 29, 2014
@OXYAMINE

After upgrade I can not start daemon!

Traceback (most recent call last):
File "/usr/local/bin/dynamic-dynamodb", line 22, in
import dynamic_dynamodb
File "/usr/local/lib/python2.6/dist-packages/dynamic_dynamodb/init.py", line 29, in
from dynamic_dynamodb.core import dynamodb, gsi, table
File "/usr/local/lib/python2.6/dist-packages/dynamic_dynamodb/core/dynamodb.py", line 12, in
from dynamic_dynamodb.log_handler import LOGGER as logger
File "/usr/local/lib/python2.6/dist-packages/dynamic_dynamodb/log_handler.py", line 25, in
import config_handler
File "/usr/local/lib/python2.6/dist-packages/dynamic_dynamodb/config_handler.py", line 4, in
CONFIGURATION = config.get_configuration()
File "/usr/local/lib/python2.6/dist-packages/dynamic_dynamodb/config/init.py", line 121, in get_configuration
check_gsi_rules(configuration)
File "/usr/local/lib/python2.6/dist-packages/dynamic_dynamodb/config/__init
.py", line 318, in __check_gsi_rules
if gsi['sns_message_types']:
KeyError: 'sns_message_types'

@sebdah
Owner
sebdah commented Mar 31, 2014

Thanks @OXYAMINE, that is fixed in 1.10.3. A problem with parsing default options for GSIs was behind that.

@OXYAMINE
OXYAMINE commented Apr 1, 2014

thank you

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment