We have some performance troubles with a database of our biggest customer. Foxhound did not report any problems. Usage of CPU(1-15%), Disk and Active requests (mostly around 5, very rare a unschelded task, very very rare a blocked connection).

When I open Performance Monitor I see some things that I do not understand: 1. In the tabpage "Statements" I see a slow query that should be very fast, there are 120 rows in the tabel. Strange is that there is a large Idle time. (see below a copy of the screen *1) What does that Idle time mean and how can I prevent that large idle times?

  1. In the tabpage "Analysis" I see under section 'Is performance limited by workers?' a few times: Worker-bound for x sec However the mulitpogrammaging level is set between 24 and 80, and when I look in foxhound it is most of the times 24 with a low active requests. How can I prevent that worker-boud? In Foxhound I see nothing special at the same time. All seems to be ok.
*1)
Execute Statement Properties
============================

General
-------
Operation type: Execute Statement
Date: Today 8:38:39
Execution time: 4,19 sec
Connection: 729443 (WRO)
Statement timing:
Prepare statement < 1 ms
Execute statement < 1 ms
Fetch results < 1 ms
**Idle 4,19 sec**
Blocked 0 ms
Statement handle: 668839
Cursor handle: 79016

SQL
---
select "event_jobs"."nummer","event_jobs"."user","event_jobs"."sql","event_jobs"."status","event_jobs"."omschrijving","event_jobs"."usertxt","event_jobs"."result","event_jobs"."start","event_jobs"."stop","event_jobs"."scheduled_for","event_jobs"."window","event_jobs"."id",cast(cast("datediff"("second","start","stop") as integer)/60 as integer) as "minuten",cast("datediff"("second","start","stop") as integer)-(cast(cast("datediff"("second","start","stop") as integer)/60 as integer))*60 as "seconden" from "event_jobs" where("event_jobs"."status" <= 3) and("event_jobs"."user" = 160)

Plan
----
event_jobs<seq>{4}

Stored SQL
----------
This operation did not run any stored SQL.

Blocking
--------
This operation did not block.

Connection
----------
Connected: Before profiling started
Disconnected: Still connected
max_temp_space: 0
max_priority: normal
timestamp_format: yyyy-mm-dd hh:nn:ss.ssssss
preserve_source_format: On
optimization_workload: Mixed
time_zone: 
optimization_goal: First-row
post_login_procedure: dbo.sa_post_login_procedure
debug_messages: Off
st_geometry_on_invalid: Error
AppInfo: IP=192.168.87.34;HOST=TSNW02;OSUSER=wessel;OS='Windows 2012R2 Build 9200 ';EXE='C:\Program Files (x86)\TSD\WinTreeClient\bin\wintree.exe';PID=0x1001c;THREAD=0xae6c;VERSION=17.0.10.6057;API=ODBC;TIMEZONEADJUSTMENT=120
max_plans_cached: 20
string_rtruncation: Off
update_statistics: On
subsume_row_locks: On
global_database_id: 2147483647
extended_join_syntax: On
first_day_of_week: 7
login_procedure: DBA.login_check
checkpoint_time: 60
ansi_permissions: On
timestamp_with_time_zone_format: yyyy-mm-dd hh:nn:ss.ssssss +hh:nn
http_session_timeout: 30
conn_auditing: On
request_timeout: 0
cooperative_commit_timeout: 250
synchronize_mirror_on_commit: Off
st_geometry_asbinary_format: WKB
TimeZoneAdjustment: 120
date_order: YMD
min_role_admins: 1
prevent_article_pkey_update: On
max_query_tasks: 1
remote_idle_timeout: 15
audit_log: 
blocking: On
max_recursive_iterations: 100
st_geometry_astext_format: WKT
oem_string: 
user_estimates: Override-magic
SessionTimeout: 0
ansi_close_cursors_on_rollback: Off
db_publisher: -1
http_connection_pool_timeout: 60
integrated_server_name: 
sql_flagger_error_level: Off
continue_after_raiserror: Off
webservice_sessionid_name: SessionID
return_date_time_as_string: Off
java_location: 
st_geometry_interpolation: relative-tolerance-percent=.3
pinned_cursor_percent_of_cache: 10
UserID: WRO
fire_triggers: On
precision: 30
st_geometry_describe_type: char
cooperative_commits: On
materialized_view_optimization: Stale
conversion_error: On
disk_sandbox: Off
tsql_variables: Off
for_xml_null_treatment: Omit
progress_messages: Off
updatable_statement_isolation: 0
verify_password_function: 
ansi_blanks: Off
isolation_level: 0
sort_collation: Internal
date_format: yyyy-mm-dd
divide_by_zero_error: On
on_charset_conversion_failure: Ignore
ansi_update_constraints: Off
auditing: Off
optimization_level: 9
max_statement_count: 50
row_counts: Off
max_client_statements_cached: 10
Database: bootenco
priority: normal
close_on_endtrans: On
st_geometry_asxml_format: GML
chained: On
odbc_distinguish_char_and_varchar: Off
allow_write_client_file: Off
blocking_timeout: 0
allow_read_client_file: Off
suppress_tds_debugging: Off
cis_option: 0
query_mem_timeout: -1
delayed_commits: Off
time_zone_adjustment: 120
truncate_timestamp_values: Off
default_dbspace: 
delayed_commit_timeout: 500
nearest_century: 0
uuid_has_hyphens: On
tsql_outer_joins: Off
collect_statistics_on_dml_updates: On
non_keywords: 
recovery_time: 2
rollback_on_deadlock: On
tds_empty_string_is_null: Off
auto_commit_on_create_local_temp_index: Off
java_class_path: 
http_connection_pool_basesize: 10
read_past_deleted: On
time_format: hh:nn:ss
Name: WINTREE-11#1
wait_for_commit: Off
reserved_keywords: 
allow_snapshot_isolation: Off
scale: 6
dedicated_task: Off
extern_login_credentials: Effective_user
prefetch: Conditional
quoted_identifier: On
log_deadlocks: On
odbc_describe_binary_as_varbinary: Off
max_cursor_count: 50
min_password_length: 0
blocking_others_timeout: 0
default_timestamp_increment: 1
IdleTimeout: 0
ansinull: On
ansi_substring: On
allow_nulls_by_default: On
max_connections: 32766
trusted_certificates_file: 
webservice_namespace_host: 
HasSecuredFeature: No
java_vm_options: 
temp_space_limit_check: On
background_priority: Off
on_tsql_error: Conditional
cis_rowset_size: 50
sql_flagger_warning_level: Off

asked 28 Apr, 03:16

HansTSD's gravatar image

HansTSD
1457914
accept rate: 33%

edited 29 Apr, 02:58

Volker%20Barth's gravatar image

Volker Barth
37.4k343510776

I have no clue, and Martins' suggestions seem reasonable, and with isolation level 0 it can't be blocked by other connections unless exclusive access was given to another transaction.

Is that query part of a longer transaction or does it run on its own (i.e. does the connection a commit right before and after that query)?

Is there a particular reason you are using "optimization_goal: First-row" instead of teh default "All-rows"?

(29 Apr, 03:08) Volker Barth

Volker is correct to mention optimization_goal First-row; changing that might make all your troubles go away.

It is not clear how "execution time" and "idle" are defined for the SQL Anywhere 17 Profiler (dbprof)...

Execution time: 4,19 sec
**Idle 4,19 sec**

...or why they are strangely the same :)

Foxhound 5's definitions are found here:

Database-level: Executing, Idle, Waiting Conns https://www.risingroad.com/foxhound-5-0/foxhound5_help/foxhound_history.html#multi_Executing

Connection-level: Waiting Time, Busy, Wait, Idle https://www.risingroad.com/foxhound-5-0/foxhound5_help/foxhound_history.html#conn_waiting

In particular, connection "idle time" is not the same as "waiting", it's the part left over after "busy" and "waiting"...

total_time = time since LoginTime
busy_time  = ReqTimeActive - ReqTimeBlockIO - ReqTimeBlockContention - ReqTimeBlockLock
wait_time  = ReqTimeUnscheduled + ReqTimeBlockIO + ReqTimeBlockContention + ReqTimeBlockLock 
idle_time  = total_time - busy_time - wait_time

...I'd love to look at your foxhound5.db file :)

About those funky ReqCountActive and ReqCountUnscheduled numbers: From time to time, over the years, various SQL Anywhere properties have returned wildly invalid values. These problems come and go, and they don't cause much grief (to me) any more because Foxhound now checks everything for reasonableness and ignores the outliers; i.e., treats them as zero.

permanent link

answered 13 hours ago

Breck%20Carter's gravatar image

Breck Carter
31.4k5086941015
accept rate: 20%

edited 13 hours ago

maybe it needed to wait for a checkpoint or file grow to finish?

permanent link

answered 28 Apr, 05:23

Martin's gravatar image

Martin
8.8k122158246
accept rate: 14%

The optimization setting I wille check. Thx.

It looks there is some settings wrong. I have installed Foxhoud a couple of weeks ago. That showed no really problems. The customer does have a new very fast server with 113G memory, the chache is 35G (initial set) and is never increased. (the server was replaced by a new one recently to solve the perfomance problem, helping a little)

The CPU is most of the time around 2% to 5%. In taskmanager nothing wrong to see. Low CPU, harddisk and network.

But when the users are very busy the server is sometimes unreachable or very slow. Even a 'select * from dummy' can take seconds (seen a few times)

When I look with sa_performance_diagonistics() I see that for all connections the ReqCountActive and ReqCountUnschedulded are the same. The highest values are 492.552 for ReqCountUnscheduld and 492.553 for RegCountActive. That looks not OK to me..?

The appliaction is old and calls a lot of heavy queries with a lot of nested selects. We will a look at that of course. But it seems that only a small part of the server capacity is used. How is that possible? What setting can cause this strange behavior? (max_query_task is set to 1)

Any clues..?

permanent link

answered 03 May, 06:14

HansTSD's gravatar image

HansTSD
1457914
accept rate: 33%

Two questions: 1 This is a physical server, isn't it? (ie not a VM) 2 Do you have any back-up software running that uses MS Shadow Copy? If so do you have the SQL Anywhere Volume Shadow Copy Service installed and running?

(2 days ago) Justin Willey
Your answer
toggle preview

Follow this question

By Email:

Once you sign in you will be able to subscribe for any updates here

By RSS:

Answers

Answers and Comments

Markdown Basics

  • *italic* or _italic_
  • **bold** or __bold__
  • link:[text](http://url.com/ "title")
  • image?![alt text](/path/img.jpg "title")
  • numbered list: 1. Foo 2. Bar
  • to add a line break simply add two spaces to where you would like the new line to be.
  • basic HTML tags are also supported

Question tags:

×266

question asked: 28 Apr, 03:16

question was seen: 120 times

last updated: 13 hours ago