|
Hi,
We run postgres 9.3.3 on Centos 6.3, kernel 2.6.32-431.3.1. Every once in a while, we see postgres processes spinning on semop:
Here is an output from an strace on a delete process:
root@site-db01a:~ # strace -p 53744
Process 53744 attached - interrupt to quit
semop(21692498, {{6, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20480045, {{15, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20185124, {{3, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20185124, {{3, 1, 0}}, 1) = 0
semop(20185124, {{3, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21135425, {{14, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21692498, {{6, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21266501, {{4, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21692498, {{6, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20250662, {{0, 1, 0}}, 1) = 0
semop(21135425, {{14, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20250662, {{0, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21266501, {{6, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20185124, {{3, 1, 0}}, 1) = 0
semop(20185124, {{3, 1, 0}}, 1) = 0
semop(20250662, {{0, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21626960, {{7, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20185124, {{3, 1, 0}}, 1) = 0
semop(21266501, {{4, 1, 0}}, 1) = 0
semop(21266501, {{4, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20119586, {{5, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20185124, {{3, 1, 0}}, 1) = 0
semop(21200963, {{5, 1, 0}}, 1) = 0
semop(21135425, {{14, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21233732, {{9, 1, 0}}, 1) = 0
semop(21266501, {{7, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20185124, {{3, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21266501, {{4, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20185124, {{3, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21135425, {{14, 1, 0}}, 1) = 0
semop(20185124, {{3, 1, 0}}, 1) = 0
semop(21233732, {{9, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20774966, {{7, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20185124, {{3, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21233732, {{9, 1, 0}}, 1) = 0
semop(20185124, {{3, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(20185124, {{3, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
…
(output truncated)
…
semop(21233732, {{9, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21168194, {{10, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21168194, {{10, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21168194, {{10, 1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21561422, {{12, -1, 0}}, 1) = 0
semop(21168194, {{10, 1, 0}}, 1) = 0
sendto(3, "<134>Jun 26 12:23:30 postgres[53"..., 495, MSG_NOSIGNAL, NULL, 0) = 495
sendto(3, "<134>Jun 26 12:23:30 postgres[53"..., 258, MSG_NOSIGNAL, NULL, 0) = 258
sendto(10, "\2\0\0\0000\2\0\0001@\0\0\5\0\0\0\17\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 560, 0, NULL, 0) = 560
sendto(11, "1\0\0\0\0042\0\0\0\4n\0\0\0\4C\0\0\0\rDELETE 0\0Z\0\0"..., 35, 0, NULL, 0) = 35
recvfrom(11, "P\0\0\1\220\0delete from sym_data where"..., 8192, 0, NULL, NULL) = 576
lseek(27, 0, SEEK_END) = 499105792
lseek(28, 0, SEEK_END) = 19578880
lseek(29, 0, SEEK_END) = 4120576
lseek(30, 0, SEEK_END) = 20733952
lseek(31, 0, SEEK_END) = 20070400
lseek(32, 0, SEEK_END) = 491520
lseek(14, 0, SEEK_END) = 115073024
lseek(21, 0, SEEK_END) = 158318592
lseek(49, 0, SEEK_END) = 45277184
lseek(15, 0, SEEK_END) = 252067840
lseek(16, 0, SEEK_END) = 22503424
lseek(44, 0, SEEK_END) = 35635200
lseek(45, 0, SEEK_END) = 64151552
lseek(14, 0, SEEK_END) = 115073024
lseek(21, 0, SEEK_END) = 158318592
lseek(49, 0, SEEK_END) = 45277184
semop(21561422, {{12, -1, 0}}, 1) = 0
lseek(27, 0, SEEK_END) = 499105792
sendto(11, "1\0\0\0\0042\0\0\0\4n\0\0\0\4C\0\0\0\rDELETE 0\0Z\0\0"..., 35, 0, NULL, 0) = 35
recvfrom(11, "P\0\0\1\220\0delete from sym_data where"..., 8192, 0, NULL, NULL) = 576
lseek(27, 0, SEEK_END) = 499105792
lseek(28, 0, SEEK_END) = 19578880
lseek(29, 0, SEEK_END) = 4120576
lseek(30, 0, SEEK_END) = 20733952
lseek(31, 0, SEEK_END) = 20070400
lseek(32, 0, SEEK_END) = 491520
lseek(14, 0, SEEK_END) = 115073024
lseek(21, 0, SEEK_END) = 158318592
lseek(49, 0, SEEK_END) = 45277184
lseek(15, 0, SEEK_END) = 252067840
lseek(16, 0, SEEK_END) = 22503424
lseek(44, 0, SEEK_END) = 35635200
lseek(45, 0, SEEK_END) = 64151552
lseek(14, 0, SEEK_END) = 115073024
lseek(21, 0, SEEK_END) = 158318592
lseek(49, 0, SEEK_END) = 45277184
lseek(27, 0, SEEK_END) = 499105792
Running a perf on the process showed this:
Samples: 33K of event 'cycles', Event count (approx.): 20693251070 26.16% postmaster postgres [.] 0x0000000000188450 21.13% postmaster postgres [.] hash_search_with_hash_value 10.47% postmaster postgres [.] heap_page_prune_opt 4.21% postmaster postgres [.] LWLockAcquire 3.71% postmaster postgres [.] slot_getattr 1.97% postmaster postgres [.] HeapTupleSatisfiesMVCC 1.82% postmaster postgres [.] LWLockRelease 1.48% postmaster postgres [.] ExecProject 1.19% postmaster postgres [.] bpcharne 0.98% postmaster postgres [.] MemoryContextReset 0.90% postmaster postgres [.] ExecScan 0.89% postmaster postgres [.] pglz_decompress 0.79% postmaster postgres [.] hash_any 0.77% postmaster postgres [.] LookupTupleHashEntry 0.66% postmaster postgres [.] heap_form_minimal_tuple 0.65% postmaster postgres [.] ExecProcNode 0.63% postmaster [kernel.kallsyms] [k] _spin_lock 0.58% postmaster postgres [.] heap_fill_tuple 0.52% postmaster postgres [.] ExecClearTuple 0.46% postmaster libc-2.12.so [.] __memcmp_sse4_1 0.39% postmaster postgres [.] SearchCatCache 0.38% postmaster postgres [.] heap_compute_data_size 0.35% postmaster postgres [.] ExecQual 0.35% postmaster postgres [.] ReadBufferExtended 0.34% postmaster postgres [.] palloc0 0.34% postmaster libc-2.12.so [.] memcpy 0.31% postmaster postgres [.] LockBuffer 0.28% postmaster postgres [.] deconstruct_array 0.27% postmaster postgres [.] ResourceOwnerForgetBuffer 0.25% postmaster [kernel.kallsyms] [k] sys_semtimedop 0.25% postmaster postgres [.] base_yyparse 0.25% postmaster postgres [.] hash_uint32 0.23% postmaster postgres [.] FunctionCall1Coll 0.23% postmaster postgres [.] heap_getnext 0.22% postmaster postgres [.] ReleaseBuffer 0.22% postmaster [kernel.kallsyms] [k] ipc_has_perm 0.21% postmaster postgres [.] check_stack_depth 0.21% postmaster postgres [.] hash_search 0.20% postmaster [kernel.kallsyms] [k] native_write_msr_safe 0.20% postmaster postgres [.] GetSnapshotData 0.20% postmaster libc-2.12.so [.] _int_malloc 0.19% postmaster [kernel.kallsyms] [k] schedule 0.19% postmaster postgres [.] ExecStoreTuple 0.18% postmaster [kernel.kallsyms] [k] update_curr 0.18% postmaster postgres [.] pgstat_init_function_usage 0.18% postmaster libc-2.12.so [.] __strlen_sse42 0.17% postmaster postgres [.] copyObject 0.17% postmaster postgres [.] s_lock 0.17% postmaster postgres [.] MemoryContextAllocZeroAligned 0.17% postmaster postgres [.] palloc 0.17% postmaster [kernel.kallsyms] [k] avc_has_perm_noaudit 0.16% postmaster postgres [.] core_yylex 0.15% postmaster postgres [.] pgstat_end_function_usage 0.15% postmaster libc-2.12.so [.] __strcmp_sse42 0.15% postmaster [kernel.kallsyms] [k] task_rq_lock 0.14% postmaster postgres [.] expression_tree_walker 0.14% postmaster pg_stat_statements.so [.] 0x00000000000024f3 0.14% postmaster postgres [.] FunctionCall2Coll 0.12% postmaster postgres [.] CheckForSerializableConflictOut 0.12% postmaster [kernel.kallsyms] [k] select_task_rq_fair 0.12% postmaster [kernel.kallsyms] [k] __audit_syscall_exit 0.11% postmaster postgres [.] nocachegetattr 0.11% postmaster postgres [.] pg_detoast_datum_packed 0.10% postmaster [kernel.kallsyms] [k] try_to_wake_up 0.10% postmaster libc-2.12.so [.] _int_free 0.10% postmaster postgres [.] ResourceOwnerEnlargeBuffers 0.10% postmaster postgres [.] slot_attisnull 0.09% postmaster postgres [.] ExecStoreVirtualTuple 0.09% postmaster postgres [.] slot_getsomeattrs 0.08% postmaster [kernel.kallsyms] [k] try_atomic_semop 0.08% postmaster [kernel.kallsyms] [k] tcp_ack 0.08% postmaster postgres [.] get_hash_value 0.08% postmaster postgres [.] BufTableLookup 0.08% postmaster libc-2.12.so [.] __memset_sse2 0.08% postmaster [kernel.kallsyms] [k] dequeue_entity 0.08% postmaster postgres [.] ScanKeywordLookup 0.08% postmaster [kernel.kallsyms] [k] kmem_cache_free 0.08% postmaster [kernel.kallsyms] [k] tcp_recvmsg 0.08% postmaster [kernel.kallsyms] [k] _spin_lock_irq 0.07% postmaster libc-2.12.so [.] malloc 0.07% postmaster [kernel.kallsyms] [k] idr_find 0.07% postmaster [tg3] [k] tg3_poll_work 0.07% postmaster [kernel.kallsyms] [k] enqueue_entity 0.07% postmaster postgres [.] PostgresMain 0.07% postmaster [kernel.kallsyms] [k] unroll_tree_refs 0.07% postmaster postgres [.] ExecCopySlotMinimalTuple 0.07% postmaster [kernel.kallsyms] [k] kfree 0.06% postmaster postgres [.] hashint8 0.06% postmaster [kernel.kallsyms] [k] __do_softirq 0.06% postmaster [kernel.kallsyms] [k] dequeue_task_fair 0.06% postmaster postgres [.] DirectFunctionCall1Coll 0.06% postmaster [kernel.kallsyms] [k] tcp_rcv_established 0.06% postmaster [kernel.kallsyms] [k] update_queue 0.06% postmaster postgres [.] pg_encoding_mbcliplen 0.06% postmaster [kernel.kallsyms] [k] resched_task 0.06% postmaster [kernel.kallsyms] [k] copy_user_generic_string 0.06% postmaster postgres [.] LockAcquireExtended 0.06% postmaster [kernel.kallsyms] [k] find_busiest_group 0.06% postmaster postgres [.] ResourceOwnerRememberBuffer 0.05% postmaster [kernel.kallsyms] [k] enqueue_task 0.05% postmaster postgres [.] mcv_selectivity 0.05% postmaster [kernel.kallsyms] [k] thread_return 0.05% postmaster [kernel.kallsyms] [k] pid_vnr 0.05% postmaster [kernel.kallsyms] [k] audit_syscall_entry 0.05% postmaster [kernel.kallsyms] [k] __local_bh_enable 0.05% postmaster [kernel.kallsyms] [k] rcu_procesa_gp_end
I ran an ipcs and was able to see the semaphore, and get its id:
root@site-db01a:~ # ipcs -c -s | grep 21561422 21561422 600 postgres postgres postgres postgres
But I’m not sure where to go next. Is there a resource contention that this is indicating, and if so, any way to tell what the contention is on?
~Karthik |
